diff --git a/Build/index.ts b/Build/index.ts index 7f782409..b1ee784c 100644 --- a/Build/index.ts +++ b/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(), diff --git a/Build/lib/download-stats.ts b/Build/lib/download-stats.ts index 1df606ac..a1e10a24 100644 --- a/Build/lib/download-stats.ts +++ b/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, - usefulBytes: number, - wastedBytes: number, + totalDecodedBytes: number, + usefulDecodedBytes: 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, - usefulBytes: 0, - wastedBytes: 0, + totalDecodedBytes: 0, + usefulDecodedBytes: 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; - const bodyDuration = attempt.bodyStartedAt == null ? null : attempt.endedAt - attempt.bodyStartedAt; - const speed = bodyDuration == null ? 'n/a' : formatDownloadSpeed(attempt.bytes, bodyDuration); + : attempt.decodedBodyStartedAt - attempt.headersAt; + const encodedBodyDuration = attempt.encodedBodyStartedAt == null || attempt.encodedBodyEndedAt == null + ? 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), - speed, + `encoded=${prettyTraffic(attempt.encodedBytes)}`, + 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.usefulBytes += snapshot.usefulBytes; - stats.wastedBytes += snapshot.wastedBytes; + stats.totalDecodedBytes += snapshot.totalDecodedBytes; + stats.usefulDecodedBytes += snapshot.usefulDecodedBytes; + 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)}`, - `transferred=${prettyTraffic(stats.totalBytes)}`, - `hedge-waste=${prettyTraffic(stats.wastedBytes)}`, - `avg=${formatDownloadSpeed(stats.totalBytes, duration)}`, + `encoded-useful=${prettyTraffic(stats.usefulEncodedBytes)}`, + `encoded-transferred=${prettyTraffic(stats.totalEncodedBytes)}`, + `encoded-hedge-waste=${prettyTraffic(stats.wastedEncodedBytes)}`, + `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}`, diff --git a/Build/lib/fetch-assets.ts b/Build/lib/fetch-assets.ts index 7c10e8f3..7245d610 100644 --- a/Build/lib/fetch-assets.ts +++ b/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, -// while larger responses making healthy progress will not be raced merely -// because their total download time exceeds three seconds. +// This threshold is evaluated against encoded response bytes, before fetch() +// decompresses them. 1 MiB/s is about 8.4 Mbps on the network, so a source +// 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, - bytesReceived: number, + bodyConsumptionStartedAt: number | null, + 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, - bytesReceived: 0, + bodyConsumptionStartedAt: null, + 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 attemptBytes = 0; + let decodedBodyStartedAt: number | null = null; + 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 }); - headersAt = downloadTimestamp(); + const res = await $$fetch(url, { signal: controller.signal, ...defaultRequestInit }, { + 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({ transform(chunk, streamController) { - attemptBytes += chunk.byteLength; - if (isPrimary) { - primaryProgress.bytesReceived += chunk.byteLength; - } + decodedBytes += 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); }); diff --git a/Build/lib/fetch-retry.ts b/Build/lib/fetch-retry.ts index 39fc9cb6..c3d6b9e2 100644 --- a/Build/lib/fetch-retry.ts +++ b/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) { - init.dispatcher = agent; +export async function $$fetch( + url: RequestInfo, + init: RequestInit = defaultRequestInit, + progress?: FetchResponseProgress +) { + init.dispatcher = progress == null ? agent : createResponseProgressDispatcher(progress); try { const res = await undici.fetch(url, init);