Chore: better download stat report

Build/index.ts

@@ -120,11 +120,11 @@ const buildFinishedLock = path.join(ROOT_DIR, '.BUILD_FINISHED');
     // write a file to demonstrate that the build is finished
     fs.writeFileSync(buildFinishedLock, 'BUILD_FINISHED\n');
 
+    printExternalDownloadStats();
     traces.forEach((t) => {
       printTraceResult(t);
     });
     printStats(traces);
-    printExternalDownloadStats();
 
     await Promise.all([
       microsoftCdnWorker.end(),

Build/lib/download-stats.ts

@@ -1,5 +1,6 @@
 import picocolors from 'picocolors';
 import { createPrettyBits, prettyBandwidth, prettyTraffic } from 'xbits';
+import { appendArrayInPlace } from 'foxts/append-array-in-place';
 
 export type ExternalDownloadOutcome = 'winner' | 'aborted' | 'failed';
 
@@ -9,17 +10,25 @@ export interface ExternalDownloadAttempt {
   outcome: ExternalDownloadOutcome,
   startedAt: number,
   headersAt: number | null,
-  bodyStartedAt: number | null,
+  decodedBodyStartedAt: number | null,
+  encodedBodyStartedAt: number | null,
+  encodedBodyEndedAt: number | null,
   endedAt: number,
-  bytes: number
+  decodedBytes: number,
+  encodedBytes: number,
+  contentEncoding: string | null
 }
 
 export interface ExternalDownloadStatsSnapshot {
+  attempts: ExternalDownloadAttempt[],
   startedAt: number | null,
   endedAt: number | null,
-  totalBytes: number,
+  totalDecodedBytes: number,
-  usefulBytes: number,
+  usefulDecodedBytes: number,
-  wastedBytes: number,
+  wastedDecodedBytes: number,
+  totalEncodedBytes: number,
+  usefulEncodedBytes: number,
+  wastedEncodedBytes: number,
   winners: number,
   aborted: number,
   failed: number
@@ -27,11 +36,15 @@ export interface ExternalDownloadStatsSnapshot {
 
 function createEmptySnapshot(): ExternalDownloadStatsSnapshot {
   return {
+    attempts: [],
     startedAt: null,
     endedAt: null,
-    totalBytes: 0,
+    totalDecodedBytes: 0,
-    usefulBytes: 0,
+    usefulDecodedBytes: 0,
-    wastedBytes: 0,
+    wastedDecodedBytes: 0,
+    totalEncodedBytes: 0,
+    usefulEncodedBytes: 0,
+    wastedEncodedBytes: 0,
     winners: 0,
     aborted: 0,
     failed: 0
@@ -62,36 +75,60 @@ function formatDuration(duration: number | null) {
   return duration == null ? 'n/a' : `${duration.toFixed(1)}ms`;
 }
 
+function formatCompressionRatio(decodedBytes: number, encodedBytes: number) {
+  return encodedBytes <= 0 ? 'n/a' : `${(decodedBytes / encodedBytes).toFixed(2)}x`;
+}
+
 export function recordExternalDownloadAttempt(attempt: ExternalDownloadAttempt) {
+  stats.attempts.push(attempt);
   stats.startedAt = stats.startedAt == null ? attempt.startedAt : Math.min(stats.startedAt, attempt.startedAt);
   stats.endedAt = stats.endedAt == null ? attempt.endedAt : Math.max(stats.endedAt, attempt.endedAt);
-  stats.totalBytes += attempt.bytes;
+  stats.totalDecodedBytes += attempt.decodedBytes;
+  stats.totalEncodedBytes += attempt.encodedBytes;
 
   if (attempt.outcome === 'winner') {
     stats.winners++;
-    stats.usefulBytes += attempt.bytes;
+    stats.usefulDecodedBytes += attempt.decodedBytes;
+    stats.usefulEncodedBytes += attempt.encodedBytes;
   } else {
-    stats.wastedBytes += attempt.bytes;
+    stats.wastedDecodedBytes += attempt.decodedBytes;
+    stats.wastedEncodedBytes += attempt.encodedBytes;
     if (attempt.outcome === 'aborted') {
       stats.aborted++;
     } else {
       stats.failed++;
     }
   }
+}
 
+function printExternalDownloadAttempt(attempt: ExternalDownloadAttempt) {
   const ttfb = attempt.headersAt == null ? null : attempt.headersAt - attempt.startedAt;
-  const queueWait = attempt.headersAt == null || attempt.bodyStartedAt == null
+  const queueWait = attempt.headersAt == null || attempt.decodedBodyStartedAt == null
     ? null
-    : attempt.bodyStartedAt - attempt.headersAt;
+    : attempt.decodedBodyStartedAt - attempt.headersAt;
-  const bodyDuration = attempt.bodyStartedAt == null ? null : attempt.endedAt - attempt.bodyStartedAt;
+  const encodedBodyDuration = attempt.encodedBodyStartedAt == null || attempt.encodedBodyEndedAt == null
-  const speed = bodyDuration == null ? 'n/a' : formatDownloadSpeed(attempt.bytes, bodyDuration);
+    ? null
+    : attempt.encodedBodyEndedAt - attempt.encodedBodyStartedAt;
+  const decodedBodyDuration = attempt.decodedBodyStartedAt == null
+    ? null
+    : attempt.endedAt - attempt.decodedBodyStartedAt;
+  const encodedSpeed = encodedBodyDuration == null
+    ? 'n/a'
+    : formatDownloadSpeed(attempt.encodedBytes, encodedBodyDuration);
+  const decodedSpeed = decodedBodyDuration == null
+    ? 'n/a'
+    : formatDownloadSpeed(attempt.decodedBytes, decodedBodyDuration);
 
   console.log(
     picocolors.gray('[external download]'),
     attempt.kind,
     attempt.outcome,
-    prettyTraffic(attempt.bytes),
+    `encoded=${prettyTraffic(attempt.encodedBytes)}`,
-    speed,
+    encodedSpeed,
+    `decoded=${prettyTraffic(attempt.decodedBytes)}`,
+    decodedSpeed,
+    `ratio=${formatCompressionRatio(attempt.decodedBytes, attempt.encodedBytes)}`,
+    `encoding=${attempt.contentEncoding ?? 'identity'}`,
     `ttfb=${formatDuration(ttfb)}`,
     `queue=${formatDuration(queueWait)}`,
     attempt.url
@@ -103,15 +140,19 @@ export function mergeExternalDownloadStats(snapshot: ExternalDownloadStatsSnapsh
     return;
   }
 
+  appendArrayInPlace(stats.attempts, snapshot.attempts);
   if (snapshot.startedAt != null) {
     stats.startedAt = stats.startedAt == null ? snapshot.startedAt : Math.min(stats.startedAt, snapshot.startedAt);
   }
   if (snapshot.endedAt != null) {
     stats.endedAt = stats.endedAt == null ? snapshot.endedAt : Math.max(stats.endedAt, snapshot.endedAt);
   }
-  stats.totalBytes += snapshot.totalBytes;
+  stats.totalDecodedBytes += snapshot.totalDecodedBytes;
-  stats.usefulBytes += snapshot.usefulBytes;
+  stats.usefulDecodedBytes += snapshot.usefulDecodedBytes;
-  stats.wastedBytes += snapshot.wastedBytes;
+  stats.wastedDecodedBytes += snapshot.wastedDecodedBytes;
+  stats.totalEncodedBytes += snapshot.totalEncodedBytes;
+  stats.usefulEncodedBytes += snapshot.usefulEncodedBytes;
+  stats.wastedEncodedBytes += snapshot.wastedEncodedBytes;
   stats.winners += snapshot.winners;
   stats.aborted += snapshot.aborted;
   stats.failed += snapshot.failed;
@@ -128,13 +169,21 @@ export function printExternalDownloadStats() {
     return;
   }
 
+  console.log(picocolors.bold('[external downloads]'), `attempts=${stats.attempts.length}`);
+  stats.attempts
+    .toSorted((a, b) => a.startedAt - b.startedAt)
+    .forEach(printExternalDownloadAttempt);
+
   const duration = stats.endedAt - stats.startedAt;
   console.log(
     picocolors.bold('[external downloads total]'),
-    `useful=${prettyTraffic(stats.usefulBytes)}`,
+    `encoded-useful=${prettyTraffic(stats.usefulEncodedBytes)}`,
-    `transferred=${prettyTraffic(stats.totalBytes)}`,
+    `encoded-transferred=${prettyTraffic(stats.totalEncodedBytes)}`,
-    `hedge-waste=${prettyTraffic(stats.wastedBytes)}`,
+    `encoded-hedge-waste=${prettyTraffic(stats.wastedEncodedBytes)}`,
-    `avg=${formatDownloadSpeed(stats.totalBytes, duration)}`,
+    `encoded-avg=${formatDownloadSpeed(stats.totalEncodedBytes, duration)}`,
+    `decoded-useful=${prettyTraffic(stats.usefulDecodedBytes)}`,
+    `decoded-avg=${formatDownloadSpeed(stats.totalDecodedBytes, duration)}`,
+    `ratio=${formatCompressionRatio(stats.totalDecodedBytes, stats.totalEncodedBytes)}`,
     `wall=${formatDuration(duration)}`,
     `winner=${stats.winners}`,
     `aborted=${stats.aborted}`,

Build/lib/fetch-assets.ts

@@ -20,9 +20,10 @@ const MIN_HEDGE_DELAY = 3000;
 const HEDGE_DELAY_STEP = 1200;
 const HEDGE_SPEED_SAMPLE_INTERVAL = 1000;
 const HEDGE_QUEUE_POLL_INTERVAL = 250;
-// 1 MiB/s is about 8.4 Mbps. A source throttled to 5 Mbps will be hedged,
+// This threshold is evaluated against encoded response bytes, before fetch()
-// while larger responses making healthy progress will not be raced merely
+// decompresses them. 1 MiB/s is about 8.4 Mbps on the network, so a source
-// because their total download time exceeds three seconds.
+// throttled to 5 Mbps will be hedged, while a larger compressed response making
+// healthy progress will not be raced merely because decoding expands its body.
 const MIN_ACCEPTABLE_DOWNLOAD_BYTES_PER_SECOND = 1024 * 1024;
 
 export function isDownloadThroughputSlow(bytesReceived: number, elapsed: number) {
@@ -31,8 +32,10 @@ export function isDownloadThroughputSlow(bytesReceived: number, elapsed: number)
 
 interface PrimaryDownloadProgress {
   headersReceived: boolean,
-  bodyStartedAt: number | null,
+  bodyConsumptionStartedAt: number | null,
-  bytesReceived: number,
+  encodedBytesAtConsumptionStart: number,
+  encodedBytesReceived: number,
+  encodedBodyComplete: boolean,
   failed: boolean
 }
 
@@ -43,8 +46,10 @@ export async function fetchAssets(
   const controller = new AbortController();
   const primaryProgress: PrimaryDownloadProgress = {
     headersReceived: false,
-    bodyStartedAt: null,
+    bodyConsumptionStartedAt: null,
-    bytesReceived: 0,
+    encodedBytesAtConsumptionStart: 0,
+    encodedBytesReceived: 0,
+    encodedBodyComplete: false,
     failed: false
   };
 
@@ -61,7 +66,7 @@ export async function fetchAssets(
         return;
       }
 
-      if (primaryProgress.bodyStartedAt == null) {
+      if (primaryProgress.bodyConsumptionStartedAt == null) {
         // The response is waiting for our local body-consumption queue. This is
         // not an upstream slowdown and should not trigger a duplicate request.
         // eslint-disable-next-line no-await-in-loop -- poll until local consumption starts
@@ -69,7 +74,18 @@ export async function fetchAssets(
         continue;
       }
 
-      sampledAt ??= primaryProgress.bodyStartedAt;
+      if (primaryProgress.encodedBodyComplete) {
+        // The full encoded body is already local. Any remaining time belongs
+        // to decompression or parsing, which a fallback can not improve.
+        // eslint-disable-next-line no-await-in-loop -- wait for local processing to finish
+        await waitWithAbort(HEDGE_QUEUE_POLL_INTERVAL, controller.signal);
+        continue;
+      }
+
+      if (sampledAt == null) {
+        sampledAt = primaryProgress.bodyConsumptionStartedAt;
+        sampledBytes = primaryProgress.encodedBytesAtConsumptionStart;
+      }
       const now = performance.now();
       const sampleDuration = now - sampledAt;
 
@@ -79,12 +95,12 @@ export async function fetchAssets(
         continue;
       }
 
-      if (isDownloadThroughputSlow(primaryProgress.bytesReceived - sampledBytes, sampleDuration)) {
+      if (isDownloadThroughputSlow(primaryProgress.encodedBytesReceived - sampledBytes, sampleDuration)) {
         return;
       }
 
       sampledAt = now;
-      sampledBytes = primaryProgress.bytesReceived;
+      sampledBytes = primaryProgress.encodedBytesReceived;
       // eslint-disable-next-line no-await-in-loop -- periodically re-sample a healthy transfer
       await waitWithAbort(HEDGE_SPEED_SAMPLE_INTERVAL, controller.signal);
     }
@@ -111,8 +127,12 @@ export async function fetchAssets(
     const isPrimary = index < 0;
     const attemptStartedAt = downloadTimestamp();
     let headersAt: number | null = null;
-    let bodyStartedAt: number | null = null;
+    let decodedBodyStartedAt: number | null = null;
-    let attemptBytes = 0;
+    let encodedBodyStartedAt: number | null = null;
+    let encodedBodyEndedAt: number | null = null;
+    let decodedBytes = 0;
+    let encodedBytes = 0;
+    let contentEncoding: string | null = null;
     let finalized = false;
 
     const finalizeAttempt = (outcome: ExternalDownloadOutcome) => {
@@ -126,17 +146,42 @@ export async function fetchAssets(
         outcome,
         startedAt: attemptStartedAt,
         headersAt,
-        bodyStartedAt,
+        decodedBodyStartedAt,
+        encodedBodyStartedAt,
+        encodedBodyEndedAt,
         endedAt: downloadTimestamp(),
-        bytes: attemptBytes
+        decodedBytes,
+        encodedBytes,
+        contentEncoding
       });
     };
 
     try {
       // We intentionally acquire the body-consumption queue after receiving
       // headers. Request scheduling will be handled separately.
-      const res = await $$fetch(url, { signal: controller.signal, ...defaultRequestInit });
+      const res = await $$fetch(url, { signal: controller.signal, ...defaultRequestInit }, {
-      headersAt = downloadTimestamp();
+        onResponseStart(encoding) {
+          headersAt = downloadTimestamp();
+          contentEncoding = encoding;
+          if (isPrimary) {
+            primaryProgress.headersReceived = true;
+          }
+        },
+        onEncodedBodyChunk(bytes) {
+          encodedBodyStartedAt ??= downloadTimestamp();
+          encodedBytes += bytes;
+          if (isPrimary) {
+            primaryProgress.encodedBytesReceived += bytes;
+          }
+        },
+        onEncodedBodyEnd(completed) {
+          encodedBodyEndedAt = downloadTimestamp();
+          if (isPrimary) {
+            primaryProgress.encodedBodyComplete = completed;
+          }
+        }
+      });
+      headersAt ??= downloadTimestamp();
 
       let body = nullthrow(res.body, url + ' has an empty body');
       if (isPrimary) {
@@ -144,10 +189,7 @@ export async function fetchAssets(
       }
       body = body.pipeThrough(new TransformStream<Uint8Array, Uint8Array>({
         transform(chunk, streamController) {
-          attemptBytes += chunk.byteLength;
+          decodedBytes += chunk.byteLength;
-          if (isPrimary) {
-            primaryProgress.bytesReceived += chunk.byteLength;
-          }
           streamController.enqueue(chunk);
         }
       }));
@@ -163,9 +205,10 @@ export async function fetchAssets(
       }
 
       const arr = await queue.add(() => {
-        bodyStartedAt = downloadTimestamp();
+        decodedBodyStartedAt = downloadTimestamp();
         if (isPrimary) {
-          primaryProgress.bodyStartedAt = performance.now();
+          primaryProgress.bodyConsumptionStartedAt = performance.now();
+          primaryProgress.encodedBytesAtConsumptionStart = primaryProgress.encodedBytesReceived;
         }
         return Array.fromAsync(stream);
       });

Build/lib/fetch-retry.ts

@@ -174,6 +174,40 @@ const agent = new Agent({
   })
 );
 
+export interface FetchResponseProgress {
+  onResponseStart?: (contentEncoding: string | null) => void,
+  onEncodedBodyChunk?: (bytes: number) => void,
+  onEncodedBodyEnd?: (completed: boolean) => void
+}
+
+function createResponseProgressDispatcher(progress: FetchResponseProgress): Dispatcher {
+  return agent.compose(dispatch => (opts, handler) => dispatch(opts, {
+    onRequestStart: (...args) => handler.onRequestStart?.(...args),
+    onRequestUpgrade: (...args) => handler.onRequestUpgrade?.(...args),
+    onResponseStart(controller, statusCode, headers, statusMessage) {
+      const contentEncoding = headers['content-encoding'];
+      progress.onResponseStart?.(
+        contentEncoding == null
+          ? null
+          : (Array.isArray(contentEncoding) ? contentEncoding.join(', ') : contentEncoding)
+      );
+      return handler.onResponseStart?.(controller, statusCode, headers, statusMessage);
+    },
+    onResponseData(controller, chunk) {
+      progress.onEncodedBodyChunk?.(chunk.byteLength);
+      return handler.onResponseData?.(controller, chunk);
+    },
+    onResponseEnd(...args) {
+      progress.onEncodedBodyEnd?.(true);
+      return handler.onResponseEnd?.(...args);
+    },
+    onResponseError(...args) {
+      progress.onEncodedBodyEnd?.(false);
+      return handler.onResponseError?.(...args);
+    }
+  }));
+}
+
 function calculateRetryAfterHeader(retryAfter: string) {
   const current = Date.now();
   return new Date(retryAfter).getTime() - current;
@@ -209,8 +243,12 @@ export const defaultRequestInit = {
   }
 };
 
-export async function $$fetch(url: RequestInfo, init: RequestInit = defaultRequestInit) {
+export async function $$fetch(
-  init.dispatcher = agent;
+  url: RequestInfo,
+  init: RequestInit = defaultRequestInit,
+  progress?: FetchResponseProgress
+) {
+  init.dispatcher = progress == null ? agent : createResponseProgressDispatcher(progress);
 
   try {
     const res = await undici.fetch(url, init);