diff --git a/Build/constants/reject-data-source.ts b/Build/constants/reject-data-source.ts index 21ad21dd..0a6f7f08 100644 --- a/Build/constants/reject-data-source.ts +++ b/Build/constants/reject-data-source.ts @@ -14,9 +14,13 @@ export const HOSTS: HostsSource[] = [ export const HOSTS_EXTRA: HostsSource[] = [ // This stupid hosts blocks t.co, so we determine that this is also bullshit, so it is extra + // pgl.yoyo.org is also the slowest origin in the whole build, prefer mirrors [ - 'https://pgl.yoyo.org/adservers/serverlist.php?hostformat=hosts&showintro=0&mimetype=plaintext', - ['https://raw.githubusercontent.com/uBlockOrigin/uAssets/master/thirdparties/pgl.yoyo.org/as/serverlist'], + 'https://raw.githubusercontent.com/uBlockOrigin/uAssets/master/thirdparties/pgl.yoyo.org/as/serverlist', + [ + 'https://proxy.cdn.skk.moe/https/pgl.yoyo.org/adservers/serverlist.php?hostformat=hosts&showintro=0&mimetype=plaintext', + 'https://pgl.yoyo.org/adservers/serverlist.php?hostformat=hosts&showintro=0&mimetype=plaintext' + ], true ], // Dan Pollock's hosts file, 0.0.0.0 version is 30 KiB smaller diff --git a/Build/index.ts b/Build/index.ts index e6462cb4..948df3cd 100644 --- a/Build/index.ts +++ b/Build/index.ts @@ -31,6 +31,7 @@ import path from 'node:path'; import { ROOT_DIR } from './constants/dir'; import { isCI } from 'ci-info'; import { printExternalDownloadStats } from './lib/download-stats'; +import { printWireStats } from './lib/download-wire-stats'; import { endBuildWorkerFarm, getBuildWorkerFarm, warmBuildWorkerFarm } from './lib/build-worker-farm'; import { appendArrayInPlace } from 'foxts/append-array-in-place'; @@ -125,6 +126,7 @@ const buildFinishedLock = path.join(ROOT_DIR, '.BUILD_FINISHED'); fs.writeFileSync(buildFinishedLock, 'BUILD_FINISHED\n'); printExternalDownloadStats(); + printWireStats(); printBuildReport(traces, { elu: performance.eventLoopUtilization(eluAtStart), cpu: process.cpuUsage(cpuAtStart) diff --git a/Build/lib/download-wire-stats.ts b/Build/lib/download-wire-stats.ts new file mode 100644 index 00000000..72ff9044 --- /dev/null +++ b/Build/lib/download-wire-stats.ts @@ -0,0 +1,196 @@ +import picocolors from 'picocolors'; +import { prettyTraffic } from 'xbits'; +import { appendArrayInPlace } from 'foxts/append-array-in-place'; +import type { Dispatcher } from 'undici'; + +/** + * What actually crossed the network for one request, recorded *below* undici's + * cache interceptor. + * + * The progress dispatcher in fetch-retry.ts is composed on top of the agent, so + * the cache sits between it and the socket: on a fresh cache hit it observes a + * synthesized 200 with the full stored body and never learns that zero bytes + * were transferred. This interceptor is composed *inside* the cache instead, so + * it only ever runs when a request truly reaches an origin, and it sees the real + * status: + * + * - no record at all -> served from cache without touching the network + * - 304 -> revalidated, only headers on the wire + * - 200 -> full download + */ +export interface WireAttempt { + url: string, + statusCode: number, + /** encoded (still compressed) body bytes actually read off the socket */ + bytes: number, + startedAt: number, + headersAt: number | null, + endedAt: number | null, + contentEncoding: string | null, + /** the request carried If-None-Match / If-Modified-Since */ + conditional: boolean +} + +export interface WireStatsSnapshot { + attempts: WireAttempt[], + /** every request the build issued, counted above the cache */ + totalRequests: number +} + +function createEmptySnapshot(): WireStatsSnapshot { + return { attempts: [], totalRequests: 0 }; +} + +let stats = createEmptySnapshot(); + +/** called from the interceptor composed above undici's cache */ +export function countCacheableRequest() { + stats.totalRequests++; +} + +function headerValue(value: string | string[] | undefined | null): string | null { + if (value == null) { + return null; + } + return Array.isArray(value) ? value.join(', ') : value; +} + +/** + * Compose this BEFORE interceptors.cache() in the interceptor array. undici's + * `compose` wraps each interceptor around the previous one, so the last entry is + * the outermost — being earlier in the array is what puts this below the cache. + */ +export const wireTapInterceptor: Dispatcher.DispatcherComposeInterceptor = dispatch => (opts, handler) => { + const attempt: WireAttempt = { + url: (opts.origin?.toString() ?? '') + opts.path, + statusCode: 0, + bytes: 0, + startedAt: performance.now(), + headersAt: null, + endedAt: null, + contentEncoding: null, + conditional: false + }; + + const requestHeaders = opts.headers; + if (requestHeaders != null && !Array.isArray(requestHeaders)) { + const headers = requestHeaders as Record; + attempt.conditional = ('if-none-match' in headers) || ('if-modified-since' in headers); + } + + let recorded = false; + const record = () => { + if (recorded) { + return; + } + recorded = true; + attempt.endedAt = performance.now(); + stats.attempts.push(attempt); + }; + + return dispatch(opts, { + onRequestStart: (...args) => handler.onRequestStart?.(...args), + onRequestUpgrade: (...args) => handler.onRequestUpgrade?.(...args), + onResponseStart(controller, statusCode, headers, statusMessage) { + attempt.headersAt = performance.now(); + attempt.statusCode = statusCode; + attempt.contentEncoding = headerValue(headers['content-encoding']); + return handler.onResponseStart?.(controller, statusCode, headers, statusMessage); + }, + onResponseData(controller, chunk) { + attempt.bytes += chunk.byteLength; + return handler.onResponseData?.(controller, chunk); + }, + onResponseEnd(...args) { + record(); + return handler.onResponseEnd?.(...args); + }, + onResponseError(...args) { + record(); + return handler.onResponseError?.(...args); + } + }); +}; + +export function mergeWireStats(snapshot: WireStatsSnapshot | undefined) { + if (!snapshot) { + return; + } + appendArrayInPlace(stats.attempts, snapshot.attempts); + stats.totalRequests += snapshot.totalRequests; +} + +export function takeWireStats() { + const snapshot = stats; + stats = createEmptySnapshot(); + return snapshot; +} + +/** + * A 304 costs a full round trip to the origin but no body, so it is worth + * separating from both a real download and a free cache hit. + */ +export function printWireStats() { + const { attempts, totalRequests } = stats; + if (attempts.length === 0) { + if (totalRequests > 0) { + console.log( + picocolors.bold('[network wire]'), + picocolors.green('every request served from cache, nothing hit the network') + ); + } + return; + } + + let revalidated = 0; + let downloaded = 0; + let other = 0; + let wireBytes = 0; + let revalidationMs = 0; + + for (let i = 0, len = attempts.length; i < len; i++) { + const attempt = attempts[i]; + wireBytes += attempt.bytes; + if (attempt.statusCode === 304) { + revalidated++; + if (attempt.headersAt != null) { + revalidationMs += attempt.headersAt - attempt.startedAt; + } + } else if (attempt.statusCode >= 200 && attempt.statusCode < 300) { + downloaded++; + } else { + other++; + } + } + + const cacheHits = totalRequests - attempts.length; + + console.log( + picocolors.bold('[network wire]'), + `requests=${attempts.length}`, + `cache-hit=${cacheHits}`, + `revalidated-304=${revalidated}`, + `downloaded-200=${downloaded}`, + other > 0 ? `other=${other}` : '', + `wire-bytes=${prettyTraffic(wireBytes)}`, + revalidated > 0 ? `revalidation-rtt-total=${revalidationMs.toFixed(1)}ms` : '' + ); + + // The slowest wire requests are the ones worth mirroring or hedging, and a slow + // 304 is the most actionable of all: a full round trip that returned no data. + attempts + .toSorted((a, b) => (b.headersAt ?? b.startedAt) - b.startedAt - ((a.headersAt ?? a.startedAt) - a.startedAt)) + .slice(0, 10) + .forEach((attempt) => { + const ttfb = attempt.headersAt == null ? null : attempt.headersAt - attempt.startedAt; + console.log( + picocolors.gray('[network wire]'), + attempt.statusCode === 304 ? picocolors.cyan('304 revalidate') : String(attempt.statusCode), + `ttfb=${ttfb == null ? 'n/a' : ttfb.toFixed(1) + 'ms'}`, + `wire=${prettyTraffic(attempt.bytes)}`, + `encoding=${attempt.contentEncoding ?? 'identity'}`, + attempt.conditional ? picocolors.gray('conditional') : '', + attempt.url + ); + }); +} diff --git a/Build/lib/fetch-retry.ts b/Build/lib/fetch-retry.ts index ac423f63..bff68b7b 100644 --- a/Build/lib/fetch-retry.ts +++ b/Build/lib/fetch-retry.ts @@ -22,6 +22,7 @@ import fs from 'node:fs'; import { CACHE_DIR } from '../constants/dir'; import { isAbortErrorLike } from 'foxts/abort-error'; import { isErrorLikeObject } from 'foxts/extract-error-message'; +import { wireTapInterceptor, countCacheableRequest } from './download-wire-stats'; if (!fs.existsSync(CACHE_DIR)) { fs.mkdirSync(CACHE_DIR, { recursive: true }); @@ -162,6 +163,10 @@ const agent = new Agent({ maxRedirections: 5 }), stripCdnStalenessHeaders, + // Below the cache: only runs when a request actually reaches an origin, so it + // separates a free cache hit from a 304 revalidation round trip from a real + // download. See download-wire-stats.ts. + wireTapInterceptor, interceptors.cache({ store: new BetterSqlite3CacheStore({ loose: true, @@ -171,7 +176,13 @@ const agent = new Agent({ revalidationRetention: 7 * 24 * 60 * 60 * 1000 // 7 days }), cacheByDefault: 10 * 60 * 1000 // 10 minutes - }) + }), + // Above the cache, so it counts every request the build makes. Subtracting the + // wire-tap's count from this yields the number served without any network I/O. + dispatch => (opts, handler) => { + countCacheableRequest(); + return dispatch(opts, handler); + } ); export { agent as fetchAgent }; diff --git a/Build/trace/index.ts b/Build/trace/index.ts index 131701e9..0b8fef20 100644 --- a/Build/trace/index.ts +++ b/Build/trace/index.ts @@ -6,6 +6,8 @@ import process from 'node:process'; import { threadId } from 'node:worker_threads'; import { mergeExternalDownloadStats, takeExternalDownloadStats } from '../lib/download-stats'; import type { ExternalDownloadStatsSnapshot } from '../lib/download-stats'; +import { mergeWireStats, takeWireStats } from '../lib/download-wire-stats'; +import type { WireStatsSnapshot } from '../lib/download-wire-stats'; import { SPAN_STATUS_END, SPAN_STATUS_START, SpanCategory } from './types'; import type { RawSpan, TraceResult } from './types'; import { adjustTraceTimestamps, printBuildReport } from './report'; @@ -96,9 +98,10 @@ export function makeSpan(rawSpan: RawSpan): Span { async traceWorkerChild(name: string, factory: (rawSpan: RawSpan) => Promise>): Promise { const childSpan = traceChild(name, SpanCategory.Worker); - const { result, traceResult, workerTimeOrigin, externalDownloadStats } = await factory(childSpan.rawSpan); + const { result, traceResult, workerTimeOrigin, externalDownloadStats, wireStats } = await factory(childSpan.rawSpan); mergeWorkerTrace(childSpan, traceResult, workerTimeOrigin); mergeExternalDownloadStats(externalDownloadStats); + mergeWireStats(wireStats); childSpan.stop(); return result; } @@ -231,7 +234,8 @@ export interface WorkerJobResult { result: T, traceResult: TraceResult, workerTimeOrigin: number, - externalDownloadStats: ExternalDownloadStatsSnapshot + externalDownloadStats: ExternalDownloadStatsSnapshot, + wireStats: WireStatsSnapshot } /** @@ -256,6 +260,7 @@ export async function workerJob( result, traceResult: span.traceResult, workerTimeOrigin: performance.timeOrigin, - externalDownloadStats: takeExternalDownloadStats() + externalDownloadStats: takeExternalDownloadStats(), + wireStats: takeWireStats() }; }