diff --git a/Build/build-ai-cidr.ts b/Build/build-ai-cidr.ts index d9031b77..615b91e7 100644 --- a/Build/build-ai-cidr.ts +++ b/Build/build-ai-cidr.ts @@ -2,7 +2,7 @@ import { fastIpVersion } from 'foxts/fast-ip-version'; import { SHARED_DESCRIPTION } from './constants/description'; import { $$fetch } from './lib/fetch-retry'; import { RulesetOutput } from './lib/rules/ruleset'; -import { task } from './trace'; +import { SpanCategory, task } from './trace'; const OPENAI_VOICE_IP_URL = 'https://openai.com/chatgpt-voice.json'; @@ -67,7 +67,7 @@ export const buildAICIDR = task(require.main === module, __filename)(async (span const { cidr4, cidr6, lastUpdated } = await span.traceChildAsync('get OpenAI Voice IP ranges', async () => { const response = await $$fetch(OPENAI_VOICE_IP_URL); return parseOpenAIVoiceJSON(await response.json()); - }); + }, SpanCategory.Network); return new RulesetOutput(span, 'ai', 'ip') .withTitle('Sukka\'s Ruleset - ChatGPT Voice IP CIDR') diff --git a/Build/build-apple-cdn.ts b/Build/build-apple-cdn.ts index cc205ffd..ef544af9 100644 --- a/Build/build-apple-cdn.ts +++ b/Build/build-apple-cdn.ts @@ -1,5 +1,5 @@ import { parseFelixDnsmasqFromResp } from './lib/parse-dnsmasq'; -import { task } from './trace'; +import { SpanCategory, task } from './trace'; import { SHARED_DESCRIPTION } from './constants/description'; import { DomainsetOutput } from './lib/rules/domainset'; import { $$fetch } from './lib/fetch-retry'; @@ -7,7 +7,7 @@ import { $$fetch } from './lib/fetch-retry'; const getAppleCdnDomainsPromise = $$fetch('https://raw.githubusercontent.com/felixonmars/dnsmasq-china-list/master/apple.china.conf').then(parseFelixDnsmasqFromResp); export const buildAppleCdn = task(require.main === module, __filename)(async (span) => { - const res: string[] = await span.traceChildPromise('get apple cdn domains', getAppleCdnDomainsPromise); + const res: string[] = await span.traceChildPromise('get apple cdn domains', getAppleCdnDomainsPromise, SpanCategory.Network); return new DomainsetOutput(span, 'apple_cdn') .withTitle('Sukka\'s Ruleset - Apple CDN') diff --git a/Build/build-cdn-download-conf.worker.ts b/Build/build-cdn-download-conf.worker.ts index 55823a2d..5f668ea1 100644 --- a/Build/build-cdn-download-conf.worker.ts +++ b/Build/build-cdn-download-conf.worker.ts @@ -1,6 +1,6 @@ import path from 'node:path'; import { readFileIntoProcessedArray, fetchRemoteTextByLine } from './lib/fetch-text-by-line'; -import { task } from './trace'; +import { SpanCategory, task } from './trace'; import { SHARED_DESCRIPTION } from './constants/description'; import { appendArrayInPlace } from 'foxts/append-array-in-place'; import { SOURCE_DIR } from './constants/dir'; @@ -22,8 +22,7 @@ export const buildCdnDownloadConf = task(require.main === module, __filename)(as downloadDomainSet, steamDomainSet ] = await Promise.all([ - span.traceChildAsync( - 'download public suffix list for s3', + span.traceChild('download public suffix list for s3', SpanCategory.Network).traceAsyncFn( async () => { const trie = new HostnameTrie(); @@ -63,8 +62,7 @@ export const buildCdnDownloadConf = task(require.main === module, __filename)(as return S3OSSDomains; } ), - span.traceChildAsync( - 'load public ipfs gateway list', + span.traceChild('load public ipfs gateway list', SpanCategory.Network).traceAsyncFn( async () => { const data = await (await $$fetch('https://cdn.jsdelivr.net/gh/ipfs/public-gateway-checker@main/gateways.json')).json(); if (!Array.isArray(data)) { diff --git a/Build/build-chn-cidr.ts b/Build/build-chn-cidr.ts index 808927dc..695b7e45 100644 --- a/Build/build-chn-cidr.ts +++ b/Build/build-chn-cidr.ts @@ -1,5 +1,5 @@ import { fetchRemoteTextByLine } from './lib/fetch-text-by-line'; -import { task } from './trace'; +import { SpanCategory, task } from './trace'; import { IPListOutput } from './lib/rules/ip'; import { createFileDescription } from './constants/description'; @@ -10,7 +10,7 @@ const getChnCidrPromise = Promise.all([ ]); export const buildChnCidr = task(require.main === module, __filename)(async (span) => { - const [filteredCidr4, cidr6] = await span.traceChildPromise('download chnroutes2', getChnCidrPromise); + const [filteredCidr4, cidr6] = await span.traceChildPromise('download chnroutes2', getChnCidrPromise, SpanCategory.Network); // Can not use SHARED_DESCRIPTION here as different license const description = createFileDescription('CC BY-SA 2.0'); diff --git a/Build/build-common.ts b/Build/build-common.ts index ca3af8e6..844ec71b 100644 --- a/Build/build-common.ts +++ b/Build/build-common.ts @@ -4,7 +4,7 @@ import * as path from 'node:path'; import { readFileByLine } from './lib/fetch-text-by-line'; import { processLine } from './lib/process-line'; import type { Span } from './trace'; -import { task } from './trace'; +import { SpanCategory, task } from './trace'; import { SHARED_DESCRIPTION } from './constants/description'; import { fdir as Fdir } from 'fdir'; import { appendArrayInPlace } from 'foxts/append-array-in-place'; @@ -95,7 +95,7 @@ function processFile(span: Span, sourcePath: string) { } return [title, descriptions, lines, sgmodulePathname] as const; - }); + }, SpanCategory.FsRead); } async function transform(parentSpan: Span, sourcePath: string, relativePath: string) { diff --git a/Build/build-deprecate-files.ts b/Build/build-deprecate-files.ts index 711299bf..04f73ec2 100644 --- a/Build/build-deprecate-files.ts +++ b/Build/build-deprecate-files.ts @@ -1,6 +1,6 @@ import { OUTPUT_CLASH_DIR, OUTPUT_SURGE_DIR, PUBLIC_DIR } from './constants/dir'; import { compareAndWriteFile } from './lib/create-file'; -import { task } from './trace'; +import { SpanCategory, task } from './trace'; import path from 'node:path'; import fsp from 'node:fs/promises'; import { globSync } from 'tinyglobby'; @@ -29,7 +29,7 @@ const REMOVED_FOLDERS = [ 'Clash/Internal' ]; -export const buildDeprecateFiles = task(require.main === module, __filename)((span) => span.traceChildAsync('create deprecated files', async (childSpan) => { +export const buildDeprecateFiles = task(require.main === module, __filename)((span) => span.traceChild('create deprecated files', SpanCategory.FsWrite).traceAsyncFn(async (childSpan) => { const promises: Array> = globSync(REMOVED_FILES, { cwd: PUBLIC_DIR, absolute: true }) .map(f => fsp.rm(f, { force: true, recursive: true })); diff --git a/Build/build-domestic-direct-lan-ruleset-dns-mapping-module.ts b/Build/build-domestic-direct-lan-ruleset-dns-mapping-module.ts index f20354cf..864d9807 100644 --- a/Build/build-domestic-direct-lan-ruleset-dns-mapping-module.ts +++ b/Build/build-domestic-direct-lan-ruleset-dns-mapping-module.ts @@ -5,7 +5,7 @@ import { DIRECTS, HOSTS, LAN } from '../Source/non_ip/direct'; import type { DNSMapping } from '../Source/non_ip/direct'; import { fetchRemoteTextByLine, readFileIntoProcessedArray } from './lib/fetch-text-by-line'; import { compareAndWriteFile } from './lib/create-file'; -import { task } from './trace'; +import { SpanCategory, task } from './trace'; import type { Span } from './trace'; import { SHARED_DESCRIPTION } from './constants/description'; import { once } from 'foxts/once'; @@ -372,7 +372,7 @@ export const buildDomesticRuleset = task(require.main === module, __filename)(as async function buildLANCacheRuleset(span: Span) { const childSpan = span.traceChild('build LAN cache ruleset'); - const cacheDomainsData = await childSpan.traceChildAsync('fetch cache_domains.json', async () => (await $$fetch('https://cdn.jsdelivr.net/gh/uklans/cache-domains@master/cache_domains.json')).json()); + const cacheDomainsData = await childSpan.traceChildAsync('fetch cache_domains.json', async () => (await $$fetch('https://cdn.jsdelivr.net/gh/uklans/cache-domains@master/cache_domains.json')).json(), SpanCategory.Network); if (!cacheDomainsData || typeof cacheDomainsData !== 'object' || !('cache_domains' in cacheDomainsData) || !Array.isArray(cacheDomainsData.cache_domains)) { throw new TypeError('Invalid cache domains data'); } @@ -388,7 +388,8 @@ async function buildLANCacheRuleset(span: Span) { allDomainFiles.map( async (file) => childSpan.traceChildAsync( 'download ' + file, - async () => Array.fromAsync(await fetchRemoteTextByLine('https://cdn.jsdelivr.net/gh/uklans/cache-domains@master/' + file, true)) + async () => Array.fromAsync(await fetchRemoteTextByLine('https://cdn.jsdelivr.net/gh/uklans/cache-domains@master/' + file, true)), + SpanCategory.Network ) ) ) @@ -444,6 +445,8 @@ async function buildLANCacheRuleset(span: Span) { mihomoOutput.addDomain(domain); } + childSpan.stop(); + return Promise.all([ surgeOutput.write(), mihomoOutput.write() diff --git a/Build/build-microsoft-cdn.worker.ts b/Build/build-microsoft-cdn.worker.ts index d0c5031a..21a17cbc 100644 --- a/Build/build-microsoft-cdn.worker.ts +++ b/Build/build-microsoft-cdn.worker.ts @@ -1,4 +1,4 @@ -import { task } from './trace'; +import { SpanCategory, task } from './trace'; import { SHARED_DESCRIPTION } from './constants/description'; import { RulesetOutput } from './lib/rules/ruleset'; import { RULES, PROBE_DOMAINS, DOMAINS, DOMAIN_SUFFIXES, BLACKLIST } from './constants/microsoft-cdn'; @@ -8,7 +8,7 @@ import { appendArrayInPlace } from 'foxts/append-array-in-place'; import { extractDomainsFromFelixDnsmasq } from './lib/parse-dnsmasq'; export const buildMicrosoftCdn = task(require.main === module, __filename)(async (span) => { - const [domains, domainSuffixes] = await span.traceChildAsync('get microsoft cdn domains', async () => { + const [domains, domainSuffixes] = await span.traceChild('get microsoft cdn domains', SpanCategory.Network).traceAsyncFn(async () => { const trie = new HostnameSmolTrie(); for await (const line of await fetchRemoteTextByLine('https://raw.githubusercontent.com/felixonmars/dnsmasq-china-list/master/accelerated-domains.china.conf')) { diff --git a/Build/build-public.ts b/Build/build-public.ts index 7f410752..84d6ecd0 100644 --- a/Build/build-public.ts +++ b/Build/build-public.ts @@ -2,7 +2,7 @@ import path from 'node:path'; import fs from 'node:fs'; import fsp from 'node:fs/promises'; -import { task } from './trace'; +import { SpanCategory, task } from './trace'; import { treeDir, TreeFileType } from './lib/tree-dir'; import type { TreeType, TreeTypeArray } from './lib/tree-dir'; @@ -54,7 +54,7 @@ async function copyDirContents(srcDir: string, destDir: string, promises: Array< } export const buildPublic = task(require.main === module, __filename)(async (span) => { - await span.traceChildAsync('copy rest of the files', async () => { + await span.traceChild('copy rest of the files', SpanCategory.FsWrite).traceAsyncFn(async () => { const p: Array> = []; fs.mkdirSync(OUTPUT_MODULES_DIR, { recursive: true }); @@ -67,7 +67,8 @@ export const buildPublic = task(require.main === module, __filename)(async (span }); const html = await span - .traceChild('generate index.html') + // crawls the whole public dir; the html templating itself is trivial + .traceChild('generate index.html', SpanCategory.FsRead) .traceAsyncFn(() => treeDir(PUBLIC_DIR).then(generateHtml)); return Promise.all([ diff --git a/Build/build-reject-domainset.ts b/Build/build-reject-domainset.ts index 75ebb2fc..db46dcfa 100644 --- a/Build/build-reject-domainset.ts +++ b/Build/build-reject-domainset.ts @@ -8,7 +8,7 @@ import { processFilterRulesWithPreload } from './lib/parse-filter/filters'; import { HOSTS, ADGUARD_FILTERS, PREDEFINED_WHITELIST, DOMAIN_LISTS, HOSTS_EXTRA, DOMAIN_LISTS_EXTRA, ADGUARD_FILTERS_EXTRA, ADGUARD_FILTERS_WHITELIST, PHISHING_HOSTS_EXTRA, PHISHING_DOMAIN_LISTS_EXTRA, BOGUS_NXDOMAIN_DNSMASQ, ENFORCED_BLACKLIST_FROM_WHITELIST } from './constants/reject-data-source'; import { readFileIntoProcessedArray } from './lib/fetch-text-by-line'; -import { task } from './trace'; +import { SpanCategory, task } from './trace'; // tldts-experimental is way faster than tldts, but very little bit inaccurate // (since it is hashes based). But the result is still deterministic, which is // enough when creating a simple stat of reject hosts. @@ -220,7 +220,8 @@ export const buildRejectDomainSet = task(require.main === module, __filename)(as } } // return arr; - }) + }), + SpanCategory.Network )); return Promise.all(promises); @@ -244,7 +245,7 @@ export const buildRejectDomainSet = task(require.main === module, __filename)(as }); // whitelist - span.traceChildSync('whitelist', () => { + span.traceChild('whitelist', SpanCategory.Compute).traceSyncFn(() => { for (const domain of filterRuleWhitelistDomainSets) { rejectDomainsetOutput.whitelistDomain(domain); rejectExtraDomainsetOutput.whitelistDomain(domain); @@ -273,12 +274,13 @@ export const buildRejectDomainSet = task(require.main === module, __filename)(as }); }); + // each write() opens its own RuleOutput# span under the task span await Promise.all([ - span.traceChildAsync('write reject domainset', () => rejectDomainsetOutput.write()), - span.traceChildAsync('write reject_extra domainset', () => rejectExtraDomainsetOutput.write()), - span.traceChildAsync('write reject_phishing domainset', () => rejectPhisingDomainsetOutput.write()), - span.traceChildAsync('write reject ip list', () => rejectIPOutput.write()), - span.traceChildAsync('write reject non-ip ruleset', () => rejectNonIpRulesetOutput.write()) + rejectDomainsetOutput.write(), + rejectExtraDomainsetOutput.write(), + rejectPhisingDomainsetOutput.write(), + rejectIPOutput.write(), + rejectNonIpRulesetOutput.write() ]); // we are going to re-use rejectOutput's domainTrie and mutate it diff --git a/Build/build-speedtest-domainset.ts b/Build/build-speedtest-domainset.ts index 1d131641..bc319638 100644 --- a/Build/build-speedtest-domainset.ts +++ b/Build/build-speedtest-domainset.ts @@ -1,7 +1,7 @@ import path from 'node:path'; import tldts from 'tldts-experimental'; -import { task } from './trace'; +import { SpanCategory, task } from './trace'; import { SHARED_DESCRIPTION } from './constants/description'; import { readFileIntoProcessedArray } from './lib/fetch-text-by-line'; @@ -79,7 +79,7 @@ export const buildSpeedtestDomainSet = task(require.main === module, __filename) ) .addFromDomainset(readFileIntoProcessedArray(path.resolve(SOURCE_DIR, 'domainset/speedtest.conf'))) .addFromDomainset(readFileIntoProcessedArray(path.resolve(OUTPUT_SURGE_DIR, 'domainset/speedtest.conf'))) - .bulkAddDomain(await span.traceChildPromise('get speedtest.net servers', getSpeedtestHostsGroupsPromise)) - .bulkAddDomain(await span.traceChildPromise('get librespeed backends', getLibrespeedBackendsPromise)) + .bulkAddDomain(await span.traceChildPromise('get speedtest.net servers', getSpeedtestHostsGroupsPromise, SpanCategory.Network)) + .bulkAddDomain(await span.traceChildPromise('get librespeed backends', getLibrespeedBackendsPromise, SpanCategory.Network)) .write() ); diff --git a/Build/build-telegram.worker.ts b/Build/build-telegram.worker.ts index e7d8100d..05ee139c 100644 --- a/Build/build-telegram.worker.ts +++ b/Build/build-telegram.worker.ts @@ -1,5 +1,5 @@ // @ts-check -import { task } from './trace'; +import { SpanCategory, task } from './trace'; import { SHARED_DESCRIPTION } from './constants/description'; import { RulesetOutput } from './lib/rules/ruleset'; import { $$fetch } from './lib/fetch-retry'; @@ -16,7 +16,7 @@ const buildTelegramCIDR = task(require.main === module, __filename)(async (span) ]; const ipcidr6: string[] = []; - const date = await childSpan.traceChildAsync('fetch from official cidr list', async () => { + const date = await childSpan.traceChild('fetch from official cidr list', SpanCategory.Network).traceAsyncFn(async () => { const resp = await $$fetch('https://core.telegram.org/resources/cidr.txt'); const lastModified = resp.headers.get('last-modified'); @@ -148,7 +148,8 @@ async function fetchConfigFromBootstrapEndpoints() { export const buildMTProtoDCConfig = task(require.main === module, __filename)(async (span) => { const config = await span.traceChildAsync( 'fetch help.getConfig', - fetchConfigFromBootstrapEndpoints + fetchConfigFromBootstrapEndpoints, + SpanCategory.Network ); const backupEndpoints = await span.traceChildAsync( diff --git a/Build/download-mock-assets.worker.ts b/Build/download-mock-assets.worker.ts index e6f1c849..316d3c86 100644 --- a/Build/download-mock-assets.worker.ts +++ b/Build/download-mock-assets.worker.ts @@ -1,4 +1,4 @@ -import { task } from './trace'; +import { SpanCategory, task } from './trace'; import path from 'node:path'; import fs from 'node:fs'; import { pipeline } from 'node:stream/promises'; @@ -22,7 +22,9 @@ export const downloadMockAssets = task(require.main === module, __filename)(asyn return Promise.all(Object.entries(ASSETS_LIST).map( ([filename, url]) => span - .traceChildAsync(url, async () => { + // fetch + stream straight to disk; the transfer dominates + .traceChild(url, SpanCategory.Network) + .traceAsyncFn(async () => { const res = await $$fetch(url); if (!res.ok) { console.error(`Failed to download ${url}`); diff --git a/Build/download-previous-build.ts b/Build/download-previous-build.ts index f461d997..d812be86 100644 --- a/Build/download-previous-build.ts +++ b/Build/download-previous-build.ts @@ -1,7 +1,7 @@ import path from 'node:path'; import fs from 'node:fs'; import { pipeline } from 'node:stream/promises'; -import { task } from './trace'; +import { SpanCategory, task } from './trace'; import { extract as tarExtract } from 'tar-fs'; import type { Headers as TarEntryHeaders } from 'tar-fs'; import zlib from 'node:zlib'; @@ -34,9 +34,10 @@ export const downloadPreviousBuild = task(require.main === module, __filename)(a return GITLAB_CODELOAD_URL; } return GITHUB_CODELOAD_URL; - }); + }, SpanCategory.Network); - return span.traceChildAsync('download & extract previoud build', async () => { + // streaming download -> gunzip -> untar to disk, network dominates so that is the tag + return span.traceChildAsync('download & extract previous build', async () => { const respBody = undici.pipeline( tarGzUrl, { @@ -89,5 +90,5 @@ export const downloadPreviousBuild = task(require.main === module, __filename)(a } ) ); - }); + }, SpanCategory.Network); }); diff --git a/Build/index.ts b/Build/index.ts index 62e59a4b..105b53c1 100644 --- a/Build/index.ts +++ b/Build/index.ts @@ -22,8 +22,9 @@ import { createWorker } from './lib/worker'; import { buildPublic } from './build-public'; import { buildCloudMounterRules } from './build-cloudmounter-rules'; -import { printStats, printTraceResult, whyIsNodeRunning } from './trace'; +import { printBuildReport, whyIsNodeRunning } from './trace'; import type { TraceResult } from './trace'; +import { performance } from 'node:perf_hooks'; import { buildDeprecateFiles } from './build-deprecate-files'; import path from 'node:path'; import { ROOT_DIR } from './constants/dir'; @@ -71,6 +72,12 @@ const buildFinishedLock = path.join(ROOT_DIR, '.BUILD_FINISHED'); fs.unlinkSync(buildFinishedLock); } + // Build-wide resource baselines: how busy the main thread's event loop was + // (CPU vs. waiting on I/O) and how much CPU the whole process (incl. worker + // threads) burned relative to wall-clock. + const eluAtStart = performance.eventLoopUtilization(); + const cpuAtStart = process.cpuUsage(); + const microsoftCdnWorker = createWorker( require.resolve('./build-microsoft-cdn.worker') )(['buildMicrosoftCdn']); @@ -130,10 +137,10 @@ const buildFinishedLock = path.join(ROOT_DIR, '.BUILD_FINISHED'); fs.writeFileSync(buildFinishedLock, 'BUILD_FINISHED\n'); printExternalDownloadStats(); - traces.forEach((t) => { - printTraceResult(t); + printBuildReport(traces, { + elu: performance.eventLoopUtilization(eluAtStart), + cpu: process.cpuUsage(cpuAtStart) }); - printStats(traces); await Promise.all([ microsoftCdnWorker.end(), diff --git a/Build/lib/create-file.ts b/Build/lib/create-file.ts index 16c4d186..2d86b744 100644 --- a/Build/lib/create-file.ts +++ b/Build/lib/create-file.ts @@ -2,6 +2,7 @@ import { fastStringArrayJoin } from 'foxts/fast-string-array-join'; import fs from 'node:fs'; import path from 'node:path'; import picocolors from 'picocolors'; +import { SpanCategory } from '../trace'; import type { Span } from '../trace'; import { readFileByLine } from './fetch-text-by-line'; import { writeFile } from './misc'; @@ -37,7 +38,7 @@ async function isPreviousOutputEqual(span: Span, linesA: string[], filePath: str } return fileEqual(linesA, readFileByLine(filePath)); - }); + }, SpanCategory.FsRead); if (isEqual) { console.log(picocolors.gray(picocolors.dim(`same content, bail out writing: ${filePath}`))); @@ -81,7 +82,8 @@ export async function compareAndWriteFileInWorker(span: Span, linesA: string[], export function writeFileLines(span: Span, linesA: string[], filePath: string): Promise { return span.traceChildAsync( `writing ${filePath}`, - () => writeFile(filePath, fastStringArrayJoin(linesA, '\n') + '\n') + () => writeFile(filePath, fastStringArrayJoin(linesA, '\n') + '\n'), + SpanCategory.FsWrite ); } @@ -89,5 +91,5 @@ export function writeFileLinesSync(span: Span, linesA: string[], filePath: strin span.traceChildSync(`writing ${filePath}`, () => { fs.mkdirSync(path.dirname(filePath), { recursive: true }); fs.writeFileSync(filePath, fastStringArrayJoin(linesA, '\n') + '\n'); - }); + }, SpanCategory.FsWrite); } diff --git a/Build/lib/fetch-telegram-backup-endpoints.ts b/Build/lib/fetch-telegram-backup-endpoints.ts index 771db609..aa68ab5f 100644 --- a/Build/lib/fetch-telegram-backup-endpoints.ts +++ b/Build/lib/fetch-telegram-backup-endpoints.ts @@ -5,6 +5,7 @@ import picocolors from 'picocolors'; import { fastStringArrayJoin } from 'foxts/fast-string-array-join'; import { stableHash } from 'stable-hash'; +import { SpanCategory } from '../trace'; import type { Span } from '../trace'; import { $$fetch } from './fetch-retry'; import { getTelegramBackupIPFromBase64 } from './get-telegram-backup-ip'; @@ -37,7 +38,7 @@ async function fetchDnsEndpoints(span: Span, domain: string, traceName: string) return Object.assign(resolver, { server: ip }); }); - await span.traceChildAsync(traceName, () => Promise.all(resolvers.map(async (resolver) => { + await span.traceChild(traceName, SpanCategory.Network).traceAsyncFn(() => Promise.all(resolvers.map(async (resolver) => { try { const response = await resolver.resolveTxt(domain); const strings = response.map(result => fastStringArrayJoin(result, '')); @@ -61,7 +62,7 @@ async function fetchDnsEndpoints(span: Span, domain: string, traceName: string) } async function fetchRealtimeDatabaseEndpoints(span: Span) { - return span.traceChildAsync('backup source 2: Firebase Realtime DB', async () => { + return span.traceChild('backup source 2: Firebase Realtime DB', SpanCategory.Network).traceAsyncFn(async () => { try { const data = await (await $$fetch('https://reserve-5a846.firebaseio.com/ipconfigv3.json')).json(); if (typeof data !== 'string' || data.length !== 344) { @@ -79,7 +80,7 @@ async function fetchRealtimeDatabaseEndpoints(span: Span) { } async function fetchValueStoreEndpoints(span: Span) { - return span.traceChildAsync('backup source 3: Firebase Value Store', async () => { + return span.traceChild('backup source 3: Firebase Value Store', SpanCategory.Network).traceAsyncFn(async () => { try { const json = await (await $$fetch('https://firestore.googleapis.com/v1/projects/reserve-5a846/databases/(default)/documents/ipconfig/v3', { headers: { @@ -110,7 +111,7 @@ async function fetchValueStoreEndpoints(span: Span) { } async function fetchAppEngineEndpoints(span: Span, url: string, traceName: string) { - return span.traceChildAsync(traceName, async () => { + return span.traceChild(traceName, SpanCategory.Network).traceAsyncFn(async () => { try { const data = (await (await $$fetch(url)).text()).trim(); if (data.length !== 344) { @@ -147,7 +148,7 @@ async function fetchTestEndpoints(span: Span) { function getProductionEndpoints(span: Span) { if (productionEndpointsPromise) { - return span.traceChildAsync('reuse production backup endpoints', () => productionEndpointsPromise!); + return span.traceChildAsync('reuse production backup endpoints', () => productionEndpointsPromise!, SpanCategory.Wait); } productionEndpointsPromise = fetchProductionEndpoints(span); return productionEndpointsPromise; @@ -155,7 +156,7 @@ function getProductionEndpoints(span: Span) { function getTestEndpoints(span: Span) { if (testEndpointsPromise) { - return span.traceChildAsync('reuse test backup endpoints', () => testEndpointsPromise!); + return span.traceChildAsync('reuse test backup endpoints', () => testEndpointsPromise!, SpanCategory.Wait); } testEndpointsPromise = fetchTestEndpoints(span); return testEndpointsPromise; diff --git a/Build/lib/get-phishing-domains.ts b/Build/lib/get-phishing-domains.ts index 0decd06c..4ccf5dae 100644 --- a/Build/lib/get-phishing-domains.ts +++ b/Build/lib/get-phishing-domains.ts @@ -2,7 +2,7 @@ import picocolors from 'picocolors'; import { parse } from 'tldts-experimental'; import { appendArrayInPlaceCurried } from 'foxts/append-array-in-place'; -import { workerJob } from '../trace'; +import { SpanCategory, workerJob } from '../trace'; import type { RawSpan, WorkerJobResult } from '../trace'; import type { TldTsParsed } from './normalize-domain'; @@ -25,7 +25,7 @@ export function getPhishingDomains(rawSpan?: RawSpan, isDebug = false): Promise< const domainGroups = await Promise.all(downloads.map(task => task(childSpan))); - return childSpan.traceChildSync('calculate and handling mass phishing domains', () => { + return childSpan.traceChild('calculate and handling mass phishing domains', SpanCategory.Compute).traceSyncFn(() => { const domainArr: string[] = []; domainGroups.forEach(appendArrayInPlaceCurried(domainArr)); diff --git a/Build/lib/parse-filter/domainlists.ts b/Build/lib/parse-filter/domainlists.ts index f2b34430..67501262 100644 --- a/Build/lib/parse-filter/domainlists.ts +++ b/Build/lib/parse-filter/domainlists.ts @@ -1,6 +1,7 @@ import { fastNormalizeDomain, fastNormalizeDomainWithoutWww } from '../normalize-domain'; import { onBlackFound } from './shared'; import { fetchAssets } from '../fetch-assets'; +import { SpanCategory } from '../../trace'; import type { Span } from '../../trace'; function domainListLineCb(line: string, set: string[], meta: string, normalizeDomain = fastNormalizeDomain) { @@ -29,14 +30,14 @@ export function processDomainListsWithPreload( const lineCb = includeAllSubDomain ? domainListLineCbIncludeAllSubdomain : domainListLineCb; return (span: Span) => span.traceChildAsync(`process domainlist: ${domainListsUrl}`, async (childSpan) => { - const filterRules = await childSpan.traceChildPromise('download', downloadPromise); + const filterRules = await childSpan.traceChildPromise('download', downloadPromise, SpanCategory.Network); const domainSets: string[] = []; childSpan.traceChildSync('parse domain list', () => { for (let i = 0, len = filterRules.length; i < len; i++) { lineCb(filterRules[i], domainSets, domainListsUrl, fastNormalizeDomainWithoutWww); } - }); + }, SpanCategory.Compute); return domainSets; }); diff --git a/Build/lib/parse-filter/filters.ts b/Build/lib/parse-filter/filters.ts index 659f14b7..0262a3f4 100644 --- a/Build/lib/parse-filter/filters.ts +++ b/Build/lib/parse-filter/filters.ts @@ -1,4 +1,5 @@ import picocolors from 'picocolors'; +import { SpanCategory } from '../../trace'; import type { Span } from '../../trace'; import { fetchAssets } from '../fetch-assets'; import { onBlackFound, onWhiteFound } from './shared'; @@ -49,7 +50,7 @@ export function processFilterRulesWithPreload( filterRulesUrl: string } >(`process filter rules: ${filterRulesUrl}`, async (span) => { - const filterRules = await span.traceChildPromise('download', downloadPromise); + const filterRules = await span.traceChildPromise('download', downloadPromise, SpanCategory.Network); const whiteDomains = new Set(); const whiteDomainSuffixes = new Set(); @@ -121,7 +122,7 @@ export function processFilterRulesWithPreload( } }; - span.traceChild('parse adguard filter').traceSyncFn(() => { + span.traceChild('parse adguard filter', SpanCategory.Compute).traceSyncFn(() => { for (let i = 0, len = filterRules.length; i < len; i++) { lineCb(filterRules[i]); } diff --git a/Build/lib/parse-filter/hosts.ts b/Build/lib/parse-filter/hosts.ts index 05d38d65..dbfc7ad3 100644 --- a/Build/lib/parse-filter/hosts.ts +++ b/Build/lib/parse-filter/hosts.ts @@ -1,3 +1,4 @@ +import { SpanCategory } from '../../trace'; import type { Span } from '../../trace'; import { fetchAssets } from '../fetch-assets'; import { fastNormalizeDomainWithoutWww } from '../normalize-domain'; @@ -42,11 +43,11 @@ export function processHosts( const cb = includeAllSubDomain ? hostsLineCbIncludeAllSubdomain : hostsLineCb; return span.traceChildAsync(`process hosts: ${hostsUrl}`, async (span) => { - const filterRules = await span.traceChild('download').traceAsyncFn(() => fetchAssets(hostsUrl, mirrors, true)); + const filterRules = await span.traceChild('download', SpanCategory.Network).traceAsyncFn(() => fetchAssets(hostsUrl, mirrors, true)); const domainSets: string[] = []; - span.traceChild('parse hosts').traceSyncFn(() => { + span.traceChild('parse hosts', SpanCategory.Compute).traceSyncFn(() => { for (let i = 0, len = filterRules.length; i < len; i++) { cb(filterRules[i], domainSets, hostsUrl); } @@ -61,11 +62,11 @@ export function processHostsWithPreload(hostsUrl: string, mirrors: string[] | nu const cb = includeAllSubDomain ? hostsLineCbIncludeAllSubdomain : hostsLineCb; return (span: Span) => span.traceChildAsync(`process hosts: ${hostsUrl}`, async (span) => { - const filterRules = await span.traceChild('download').tracePromise(downloadPromise); + const filterRules = await span.traceChild('download', SpanCategory.Network).tracePromise(downloadPromise); const domainSets: string[] = []; - span.traceChild('parse hosts').traceSyncFn(() => { + span.traceChild('parse hosts', SpanCategory.Compute).traceSyncFn(() => { for (let i = 0, len = filterRules.length; i < len; i++) { cb(filterRules[i], domainSets, hostsUrl); } diff --git a/Build/lib/rules/base.ts b/Build/lib/rules/base.ts index 1c8b2222..95c5cf91 100644 --- a/Build/lib/rules/base.ts +++ b/Build/lib/rules/base.ts @@ -1,3 +1,4 @@ +import { SpanCategory } from '../../trace'; import type { Span } from '../../trace'; import { HostnameSmolTrie } from 'hntrie/smol'; import { not, nullthrow } from 'foxts/guard'; @@ -68,10 +69,15 @@ export class FileOutput { return this; }; - protected readonly span: Span; + /** + * The `RuleOutput#id` span is only opened by write(): between construction and + * write() this object merely accumulates sources, and that time already belongs + * to the sibling spans doing the downloading / reading. + */ + protected readonly parentSpan: Span; constructor($span: Span, protected readonly id: string) { - this.span = $span.traceChild('RuleOutput#' + id); + this.parentSpan = $span; } protected title: string | null = null; @@ -463,10 +469,12 @@ export class FileOutput { } write(): Promise { - return this.span.traceChildAsync('write all', async (childSpan) => { - await childSpan.traceChildAsync('done', () => this.done()); + return this.parentSpan.traceChildAsync('RuleOutput#' + this.id, async (childSpan) => { + // pendingPromise is the (untraced) reading + parsing of every source added + // via addFromRuleset / addFromDomainset, so this is waiting on fs + compute + await childSpan.traceChildAsync('done', () => this.done(), SpanCategory.Wait); - const domains = childSpan.traceChildSync('dump domain trie', () => this.dumpDomains()); + const domains = childSpan.traceChildSync('dump domain trie', () => this.dumpDomains(), SpanCategory.Compute); const title = nullthrow(this.title, 'Missing title'); const descriptions = nullthrow(this.description, 'Missing description'); @@ -505,7 +513,7 @@ export class FileOutput { ); } - childSpan.traceChildSync('write to strategies', () => this.writeToStrategies(domains)); + childSpan.traceChildSync('write to strategies', () => this.writeToStrategies(domains), SpanCategory.Compute); return childSpan.traceChildAsync('output to disk', (childSpan) => { const promises: Array> = []; @@ -521,7 +529,8 @@ export class FileOutput { isMainThread ? strategy.output(childSpan, title, descriptions, this.date, filePath) : strategy.outputInWorker(childSpan, title, descriptions, this.date, filePath) - )) + // self time here is banner + content hash; compare / writing are traced as children + ), SpanCategory.Compute) ); } diff --git a/Build/lib/rules/output.worker.ts b/Build/lib/rules/output.worker.ts index bc0aa147..af6b4e2d 100644 --- a/Build/lib/rules/output.worker.ts +++ b/Build/lib/rules/output.worker.ts @@ -1,4 +1,4 @@ -import { workerJob } from '../../trace'; +import { SpanCategory, workerJob } from '../../trace'; import type { RawSpan, WorkerJobResult } from '../../trace'; import { resolveStrategyOutputPath, reviveStrategy, writeDataToStrategies } from './strategy-write-data'; import type { OutputWorkerPayload } from './strategy-write-data'; @@ -15,7 +15,7 @@ export function writeOutput(rawSpan: RawSpan | undefined, payload: OutputWorkerP return workerJob(rawSpan, (span) => { const strategies = payload.strategies.map(reviveStrategy); - span.traceChildSync('write to strategies', () => writeDataToStrategies(payload.data, strategies)); + span.traceChildSync('write to strategies', () => writeDataToStrategies(payload.data, strategies), SpanCategory.Compute); const date = new Date(payload.dateMs); @@ -29,7 +29,9 @@ export function writeOutput(rawSpan: RawSpan | undefined, payload: OutputWorkerP // eslint-disable-next-line no-await-in-loop -- see above await childSpan.traceChildAsync( 'write ' + strategy.name, - (strategySpan) => strategy.outputInWorker(strategySpan, payload.title, payload.description, date, filePath) + (strategySpan) => strategy.outputInWorker(strategySpan, payload.title, payload.description, date, filePath), + // self time here is banner + content hash; compare / writing are traced as children + SpanCategory.Compute ); } }); diff --git a/Build/tools-dedupe-src.ts b/Build/tools-dedupe-src.ts index 542b633a..7ddb3cae 100644 --- a/Build/tools-dedupe-src.ts +++ b/Build/tools-dedupe-src.ts @@ -5,7 +5,7 @@ import { SOURCE_DIR } from './constants/dir'; import { readFileByLine } from './lib/fetch-text-by-line'; import { processLine } from './lib/process-line'; import { HostnameSmolTrie } from 'hntrie/smol'; -import { task } from './trace'; +import { SpanCategory, task } from './trace'; import { fastStringArrayJoin } from 'foxts/fast-string-array-join'; const ENFORCED_WHITELIST = [ @@ -26,7 +26,7 @@ const ENFORCED_WHITELIST = [ const DEDUPE_LIST: string[] = ['adx-static.ksosoft.com', 'dns.iqiyi.com', 'domain.expiring-soon.xyz', 'img.catwvod.xyz', 'img.vim-cn.com', 's3-zen.mds.yandex.net']; task(require.main === module, __filename)(async (span) => { - const files = await span.traceChildAsync('crawl thru all files', () => new Fdir() + const files = await span.traceChild('crawl thru all files', SpanCategory.FsRead).traceAsyncFn(() => new Fdir() .withFullPaths() .filter((filepath, isDirectory) => { if (isDirectory) return true; @@ -38,7 +38,7 @@ task(require.main === module, __filename)(async (span) => { .crawl(SOURCE_DIR) .withPromise()); - const whiteTrie = span.traceChildSync('build whitelist trie', () => { + const whiteTrie = span.traceChild('build whitelist trie', SpanCategory.Compute).traceSyncFn(() => { const trie = new HostnameSmolTrie(DEDUPE_LIST); ENFORCED_WHITELIST.forEach((item) => trie.whitelist(item)); return trie; diff --git a/Build/trace/index.ts b/Build/trace/index.ts index c2cf1151..03909daa 100644 --- a/Build/trace/index.ts +++ b/Build/trace/index.ts @@ -1,40 +1,36 @@ import { isCI } from 'ci-info'; import { noop } from 'foxts/noop'; import { basename, extname } from 'node:path'; +import { performance } from 'node:perf_hooks'; import process from 'node:process'; -import picocolors from 'picocolors'; +import { threadId } from 'node:worker_threads'; import { mergeExternalDownloadStats, takeExternalDownloadStats } from '../lib/download-stats'; import type { ExternalDownloadStatsSnapshot } from '../lib/download-stats'; +import { SPAN_STATUS_END, SPAN_STATUS_START, SpanCategory } from './types'; +import type { RawSpan, TraceResult } from './types'; +import { adjustTraceTimestamps, printBuildReport } from './report'; -export const SPAN_STATUS_START = 0; -export const SPAN_STATUS_END = 1; +export { SPAN_STATUS_START, SPAN_STATUS_END, SpanCategory, UNCATEGORIZED } from './types'; +export type { RawSpan, TraceResult, ReportedSpanCategory, SpanEventLoopUtilization } from './types'; +export { printTraceResult, printStats, printBuildReport, analyzeTraces } from './report'; +export type { BuildResourceUsage, TraceAnalysis } from './report'; const spanTag = Symbol('span'); -export interface TraceResult { - name: string, - start: number, - end: number, - children: TraceResult[] -} - -/** Pure data object — safe to transfer across Worker Thread boundaries. */ -export interface RawSpan { - traceResult: TraceResult, - status: typeof SPAN_STATUS_START | typeof SPAN_STATUS_END -} - export interface Span { [spanTag]: true, readonly rawSpan: RawSpan, readonly stop: (time?: number) => void, - readonly traceChild: (name: string) => Span, + /** Tag (or re-tag) what this span's self time is spent on */ + readonly setCategory: (category: SpanCategory) => Span, + readonly traceChild: (name: string, category?: SpanCategory) => Span, readonly traceSyncFn: (fn: (span: Span) => T) => T, readonly traceAsyncFn: (fn: (span: Span) => T | Promise) => Promise, readonly tracePromise: (promise: Promise) => Promise, - readonly traceChildSync: (name: string, fn: (span: Span) => T) => T, - readonly traceChildAsync: (name: string, fn: (span: Span) => Promise) => Promise, - readonly traceChildPromise: (name: string, promise: Promise) => Promise, + readonly traceChildSync: (name: string, fn: (span: Span) => T, category?: SpanCategory) => T, + readonly traceChildAsync: (name: string, fn: (span: Span) => T | Promise, category?: SpanCategory) => Promise, + readonly traceChildPromise: (name: string, promise: Promise, category?: SpanCategory) => Promise, + /** Always tagged {@link SpanCategory.Worker}: the self time is the IPC + waiting on the worker */ readonly traceWorkerChild: (name: string, factory: (rawSpan: RawSpan) => Promise>) => Promise, readonly traceResult: TraceResult } @@ -52,17 +48,26 @@ export function makeSpan(rawSpan: RawSpan): Span { throw new Error(`span already stopped: ${traceResult.name}`); } traceResult.end = time ?? performance.now(); + if (rawSpan.eluStart) { + const elu = performance.eventLoopUtilization(rawSpan.eluStart); + traceResult.elu = { idle: elu.idle, active: elu.active }; + } rawSpan.status = SPAN_STATUS_END; }; - const traceChild = (name: string) => createSpan(name, traceResult); + const traceChild = (name: string, category?: SpanCategory) => createSpan(name, traceResult, category); const span: Span = { [spanTag]: true, rawSpan, stop, + setCategory(category) { + traceResult.category = category; + return span; + }, traceChild, traceSyncFn(fn: (span: Span) => T) { + traceResult.sync = true; const res = fn(span); span.stop(); return res; @@ -78,12 +83,12 @@ export function makeSpan(rawSpan: RawSpan): Span { span.stop(); return res; }, - traceChildSync: (name: string, fn: (span: Span) => T): T => traceChild(name).traceSyncFn(fn), - traceChildAsync: (name: string, fn: (span: Span) => T | Promise): Promise => traceChild(name).traceAsyncFn(fn), - traceChildPromise: (name: string, promise: Promise): Promise => traceChild(name).tracePromise(promise), + traceChildSync: (name: string, fn: (span: Span) => T, category?: SpanCategory): T => traceChild(name, category).traceSyncFn(fn), + traceChildAsync: (name: string, fn: (span: Span) => T | Promise, category?: SpanCategory): Promise => traceChild(name, category).traceAsyncFn(fn), + traceChildPromise: (name: string, promise: Promise, category?: SpanCategory): Promise => traceChild(name, category).tracePromise(promise), async traceWorkerChild(name: string, factory: (rawSpan: RawSpan) => Promise>): Promise { - const childSpan = traceChild(name); + const childSpan = traceChild(name, SpanCategory.Worker); const { result, traceResult, workerTimeOrigin, externalDownloadStats } = await factory(childSpan.rawSpan); mergeWorkerTrace(childSpan, traceResult, workerTimeOrigin); mergeExternalDownloadStats(externalDownloadStats); @@ -96,18 +101,25 @@ export function makeSpan(rawSpan: RawSpan): Span { return span; } -export function createSpan(name: string, parentTraceResult?: TraceResult): Span { +export function createSpan(name: string, parentTraceResult?: TraceResult, category?: SpanCategory): Span { + const traceResult: TraceResult = { + name, + start: performance.now(), + end: 0, + thread: threadId, + children: [] + }; + if (category !== undefined) { + traceResult.category = category; + } + const rawSpan: RawSpan = { - traceResult: { - name, - start: performance.now(), - end: 0, - children: [] - }, - status: SPAN_STATUS_START + traceResult, + status: SPAN_STATUS_START, + eluStart: performance.eventLoopUtilization() }; - parentTraceResult?.children.push(rawSpan.traceResult); + parentTraceResult?.children.push(traceResult); return makeSpan(rawSpan); } @@ -123,6 +135,8 @@ export function task(importMetaMain: boolean, importMetaPath: string) { }; if (importMetaMain) { + const eluAtStart = performance.eventLoopUtilization(); + const cpuAtStart = process.cpuUsage(); const innerSpan = createSpan(taskName); process.on('uncaughtException', (error) => { @@ -136,7 +150,11 @@ export function task(importMetaMain: boolean, importMetaPath: string) { innerSpan.traceChildAsync('dummy', (childSpan) => fn(childSpan, onCleanup)).finally(() => { innerSpan.stop(); - printTraceResult(innerSpan.traceResult); + innerSpan.traceResult.timeOrigin = performance.timeOrigin; + printBuildReport([innerSpan.traceResult], { + elu: performance.eventLoopUtilization(eluAtStart), + cpu: process.cpuUsage(cpuAtStart) + }); process.nextTick(whyIsNodeRunning); process.nextTick(() => process.exit(0)); }); @@ -157,6 +175,9 @@ export function task(importMetaMain: boolean, importMetaPath: string) { cleanup(); } + // A task may run on a worker thread (via jest-worker) and hand its trace + // back to the main thread, which then needs this to re-align the clock. + runSpan.traceResult.timeOrigin = performance.timeOrigin; return runSpan.traceResult; } @@ -186,15 +207,6 @@ export async function whyIsNodeRunning() { // }; // }; -function adjustTraceTimestamps(trace: TraceResult, offset: number): TraceResult { - return { - name: trace.name, - start: trace.start + offset, - end: trace.end + offset, - children: trace.children.map(child => adjustTraceTimestamps(child, offset)) - }; -} - function mergeWorkerTrace( parentSpan: Span, workerTraceResult: TraceResult, @@ -240,67 +252,3 @@ export async function workerJob( externalDownloadStats: takeExternalDownloadStats() }; } - -export function printTraceResult(traceResult: TraceResult) { - printTree( - traceResult, - node => { - if (node.end - node.start < 0) { - return node.name; - } - return `${node.name} ${picocolors.bold(`${(node.end - node.start).toFixed(3)}ms`)}`; - } - ); -} - -function printTree(initialTree: TraceResult, printNode: (node: TraceResult, branch: string) => string) { - function printBranch(tree: TraceResult, branch: string, isGraphHead: boolean, isChildOfLastBranch: boolean) { - const children = tree.children; - - let branchHead = ''; - - if (!isGraphHead) { - branchHead = children.length > 0 ? '┬ ' : '─ '; - } - - const toPrint = printNode(tree, `${branch}${branchHead}`); - - if (typeof toPrint === 'string') { - console.log(`${branch}${branchHead}${toPrint}`); - } - - let baseBranch = branch; - - if (!isGraphHead) { - baseBranch = branch.slice(0, -2) + (isChildOfLastBranch ? ' ' : '│ '); - } - - const nextBranch = `${baseBranch}├─`; - const lastBranch = `${baseBranch}└─`; - - children.forEach((child, index) => { - const last = children.length - 1 === index; - printBranch(child, last ? lastBranch : nextBranch, false, last); - }); - } - - printBranch(initialTree, '', true, false); -} - -export function printStats(stats: TraceResult[]): void { - const longestTaskName = Math.max(...stats.map(i => i.name.length)); - const realStart = Math.min(...stats.map(i => i.start)); - const realEnd = Math.max(...stats.map(i => i.end)); - - const statsStep = ((realEnd - realStart) / 120) | 0; - - stats - .sort((a, b) => a.start - b.start) - .forEach(stat => { - console.log( - `[${stat.name}]${' '.repeat(longestTaskName - stat.name.length)}`, - ' '.repeat(((stat.start - realStart) / statsStep) | 0), - '='.repeat(Math.max(((stat.end - stat.start) / statsStep) | 0, 1)) - ); - }); -} diff --git a/Build/trace/report.test.ts b/Build/trace/report.test.ts new file mode 100644 index 00000000..c3e4da61 --- /dev/null +++ b/Build/trace/report.test.ts @@ -0,0 +1,102 @@ +import { describe, it } from 'mocha'; +import { expect } from 'earl'; +import { performance } from 'node:perf_hooks'; + +import { analyzeTraces } from './report'; +import { SpanCategory, UNCATEGORIZED } from './types'; +import type { TraceResult } from './types'; +import type { CategoryStat, TraceAnalysis } from './report'; + +function span( + name: string, + start: number, + end: number, + extra: Partial> = {}, + children: TraceResult[] = [] +): TraceResult { + return { name, start, end, thread: 0, children, ...extra }; +} + +function indexByCategory(analysis: TraceAnalysis) { + return analysis.categories.reduce>((acc, c) => { + acc[c.category] = c; + return acc; + }, {}); +} + +describe('trace report analysis', () => { + it('attributes self time as duration minus the union of (overlapping) children', () => { + const task = span('task', 0, 100, {}, [ + // two async children that overlap: 10-50 and 30-70 cover 60ms, not 80ms + span('a', 10, 50, { category: SpanCategory.Network }), + span('b', 30, 70, { category: SpanCategory.Network }), + span('c', 80, 90, { category: SpanCategory.Compute, sync: true }) + ]); + + const analysis = analyzeTraces([task]); + const byCategory = indexByCategory(analysis); + + expect(analysis.wall).toEqual(100); + expect(byCategory[UNCATEGORIZED].selfTotal).toEqual(100 - 60 - 10); + // self of leaves is their full duration, summed across the concurrent pair + expect(byCategory[SpanCategory.Network].selfTotal).toEqual(40 + 40); + // coverage de-duplicates the overlap + expect(byCategory[SpanCategory.Network].coverage).toEqual(60); + expect(byCategory[SpanCategory.Compute].selfTotal).toEqual(10); + expect(byCategory[SpanCategory.Compute].selfSync).toEqual(10); + expect(byCategory[SpanCategory.Network].selfSync).toEqual(0); + + expect(analysis.tasks[0].byCategory[SpanCategory.Network]).toEqual(80); + expect(analysis.tasks[0].byCategory[UNCATEGORIZED]).toEqual(30); + }); + + it('clips children to the parent window and never reports negative self time', () => { + // fire-and-forget child that outlives its parent + const task = span('task', 0, 50, {}, [span('late', 40, 90, { category: SpanCategory.FsWrite })]); + + const analysis = analyzeTraces([task]); + const byCategory = indexByCategory(analysis); + + expect(byCategory[UNCATEGORIZED].selfTotal).toEqual(40); + expect(byCategory[SpanCategory.FsWrite].selfTotal).toEqual(50); + expect(analysis.wall).toEqual(90); + }); + + it('skips unfinished spans but counts them', () => { + const task = span('task', 0, 10, {}, [span('never stopped', 5, 0)]); + + const analysis = analyzeTraces([task]); + + expect(analysis.unfinishedSpans).toEqual(1); + // the unfinished child does not eat into the parent's self time + expect(analysis.categories.find(c => c.category === UNCATEGORIZED)!.selfTotal).toEqual(10); + }); + + it('splits self time between the main thread and workers', () => { + const task = span('task', 0, 100, {}, [ + span('offload', 0, 100, { category: SpanCategory.Worker }, [ + span('crunch', 20, 60, { category: SpanCategory.Compute, thread: 7, sync: true }) + ]) + ]); + + const analysis = analyzeTraces([task]); + const compute = analysis.categories.find(c => c.category === SpanCategory.Compute)!; + const worker = analysis.categories.find(c => c.category === SpanCategory.Worker)!; + + expect(compute.selfOnWorkers).toEqual(40); + expect(compute.selfOnMainThread).toEqual(0); + expect(worker.selfOnMainThread).toEqual(60); + }); + + it('shifts a trace produced on another thread onto the local clock', () => { + // A worker whose clock started 1000ms after ours reports everything 1000ms early + const workerTask = span('worker task', 0, 10, { timeOrigin: performance.timeOrigin + 1000 }); + const mainTask = span('main task', 1000, 1010); + + const analysis = analyzeTraces([workerTask, mainTask]); + + expect(analysis.wallStart).toEqual(1000); + expect(analysis.wallEnd).toEqual(1010); + expect(analysis.tasks[0].node.start).toEqual(1000); + }); +}); diff --git a/Build/trace/report.ts b/Build/trace/report.ts new file mode 100644 index 00000000..64d295ad --- /dev/null +++ b/Build/trace/report.ts @@ -0,0 +1,596 @@ +import { performance } from 'node:perf_hooks'; +import { stripVTControlCharacters } from 'node:util'; +import picocolors from 'picocolors'; +import { SpanCategory, UNCATEGORIZED } from './types'; +import type { ReportedSpanCategory, SpanEventLoopUtilization, TraceResult } from './types'; + +/** Fixed display order: I/O flavours first, then compute, then the "waiting on something else" buckets */ +const CATEGORY_ORDER: ReportedSpanCategory[] = [ + SpanCategory.Network, + SpanCategory.FsRead, + SpanCategory.FsWrite, + SpanCategory.Compute, + SpanCategory.Worker, + SpanCategory.Wait, + UNCATEGORIZED +]; + +const CATEGORY_COLOR: Record string> = { + [SpanCategory.Network]: picocolors.cyan, + [SpanCategory.FsRead]: picocolors.green, + [SpanCategory.FsWrite]: picocolors.yellow, + [SpanCategory.Compute]: picocolors.magenta, + [SpanCategory.Worker]: picocolors.blue, + [SpanCategory.Wait]: picocolors.gray, + [UNCATEGORIZED]: picocolors.gray +}; + +const TOP_SPANS_PER_CATEGORY = 5; +const TOP_SPANS_OVERALL = 15; + +// --------------------------------------------------------------------------- +// Clock alignment +// --------------------------------------------------------------------------- + +export function adjustTraceTimestamps(trace: TraceResult, offset: number): TraceResult { + const adjusted: TraceResult = { + ...trace, + start: trace.start + offset, + end: trace.end + offset, + children: trace.children.map(child => adjustTraceTimestamps(child, offset)) + }; + // the clock is now the main thread's, so the marker no longer applies + delete adjusted.timeOrigin; + return adjusted; +} + +/** + * A task that ran on a worker thread reports `performance.now()` values relative + * to that thread's own `timeOrigin`. Shift them onto the current thread's clock + * so tasks can be laid out on a shared timeline. + */ +export function normalizeTraceClock(trace: TraceResult): TraceResult { + if (trace.timeOrigin == null || trace.timeOrigin === performance.timeOrigin) { + return trace; + } + return adjustTraceTimestamps(trace, trace.timeOrigin - performance.timeOrigin); +} + +// --------------------------------------------------------------------------- +// Analysis +// --------------------------------------------------------------------------- + +export interface AnalyzedSpan { + node: TraceResult, + /** Ancestor names, root task first, this span last */ + path: string[], + category: ReportedSpanCategory, + duration: number, + /** Duration not covered by any traced child */ + self: number +} + +export interface CategoryStat { + category: ReportedSpanCategory, + /** Sum of self time of all spans with this category (across all threads, concurrency included) */ + selfTotal: number, + /** Wall-clock during which at least one span of this category was in flight */ + coverage: number, + spans: number, + selfOnMainThread: number, + selfOnWorkers: number, + /** Self time of synchronous spans: guaranteed CPU, no event-loop queueing inside */ + selfSync: number, + top: AnalyzedSpan[] +} + +export interface TaskStat { + node: TraceResult, + duration: number, + /** Self time of all descendants (and the task itself) bucketed by category */ + byCategory: Record +} + +export interface TraceAnalysis { + wallStart: number, + wallEnd: number, + wall: number, + categories: CategoryStat[], + tasks: TaskStat[], + topSpans: AnalyzedSpan[], + unfinishedSpans: number +} + +type Interval = [start: number, end: number]; + +function isFinished(node: TraceResult) { + return node.end >= node.start; +} + +/** Total length covered by the union of the intervals (handles overlap, which async children routinely do) */ +function unionLength(intervals: Interval[]): number { + if (intervals.length === 0) { + return 0; + } + intervals.sort((a, b) => a[0] - b[0]); + + let total = 0; + let [curStart, curEnd] = intervals[0]; + for (let i = 1, len = intervals.length; i < len; i++) { + const [start, end] = intervals[i]; + if (start <= curEnd) { + if (end > curEnd) { + curEnd = end; + } + } else { + total += curEnd - curStart; + curStart = start; + curEnd = end; + } + } + return total + (curEnd - curStart); +} + +function selfTime(node: TraceResult): number { + const duration = node.end - node.start; + if (node.children.length === 0) { + return duration; + } + + const covered: Interval[] = []; + for (let i = 0, len = node.children.length; i < len; i++) { + const child = node.children[i]; + if (!isFinished(child)) { + continue; + } + // clip to the parent's own window: a child stopped after its parent + // (fire-and-forget) must not produce negative self time + const start = Math.max(child.start, node.start); + const end = Math.min(child.end, node.end); + if (end > start) { + covered.push([start, end]); + } + } + + return Math.max(0, duration - unionLength(covered)); +} + +function emptyByCategory(): Record { + return { + [SpanCategory.Network]: 0, + [SpanCategory.FsRead]: 0, + [SpanCategory.FsWrite]: 0, + [SpanCategory.Compute]: 0, + [SpanCategory.Worker]: 0, + [SpanCategory.Wait]: 0, + [UNCATEGORIZED]: 0 + }; +} + +export function analyzeTraces(rawTraces: TraceResult[]): TraceAnalysis { + const traces = rawTraces.map(normalizeTraceClock); + + const spans: AnalyzedSpan[] = []; + const coverageIntervals = new Map(); + const categoryStats = new Map(); + for (let i = 0, len = CATEGORY_ORDER.length; i < len; i++) { + const category = CATEGORY_ORDER[i]; + coverageIntervals.set(category, []); + categoryStats.set(category, { + category, + selfTotal: 0, + coverage: 0, + spans: 0, + selfOnMainThread: 0, + selfOnWorkers: 0, + selfSync: 0, + top: [] + }); + } + + let unfinishedSpans = 0; + let wallStart = Infinity; + let wallEnd = -Infinity; + + const walk = (node: TraceResult, path: string[], task: TaskStat) => { + const ownPath = path.concat(node.name); + + if (isFinished(node)) { + const category = node.category ?? UNCATEGORIZED; + const self = selfTime(node); + spans.push({ node, path: ownPath, category, duration: node.end - node.start, self }); + + const stat = categoryStats.get(category)!; + stat.selfTotal += self; + stat.spans++; + if (node.thread === 0) { + stat.selfOnMainThread += self; + } else { + stat.selfOnWorkers += self; + } + if (node.sync) { + stat.selfSync += self; + } + coverageIntervals.get(category)!.push([node.start, node.end]); + task.byCategory[category] += self; + + if (node.start < wallStart) wallStart = node.start; + if (node.end > wallEnd) wallEnd = node.end; + } else { + unfinishedSpans++; + } + + for (let i = 0, len = node.children.length; i < len; i++) { + walk(node.children[i], ownPath, task); + } + }; + + const tasks: TaskStat[] = traces.map((trace) => { + const task: TaskStat = { + node: trace, + duration: isFinished(trace) ? trace.end - trace.start : 0, + byCategory: emptyByCategory() + }; + walk(trace, [], task); + return task; + }); + + spans.sort((a, b) => b.self - a.self); + + const categories = CATEGORY_ORDER.map((category) => { + const stat = categoryStats.get(category)!; + stat.coverage = unionLength(coverageIntervals.get(category)!); + stat.top = spans.filter(s => s.category === category && s.self > 0).slice(0, TOP_SPANS_PER_CATEGORY); + return stat; + }); + + return { + wallStart, + wallEnd, + wall: wallEnd > wallStart ? wallEnd - wallStart : 0, + categories, + tasks, + topSpans: spans.filter(s => s.self > 0).slice(0, TOP_SPANS_OVERALL), + unfinishedSpans + }; +} + +// --------------------------------------------------------------------------- +// Formatting helpers +// --------------------------------------------------------------------------- + +function fmtMs(ms: number): string { + if (ms >= 10000) { + return `${(ms / 1000).toFixed(2)}s`; + } + if (ms >= 1000) { + return `${(ms / 1000).toFixed(3)}s`; + } + return `${ms.toFixed(1)}ms`; +} + +function fmtPercent(part: number, whole: number): string { + if (whole <= 0) { + return 'n/a'; + } + return `${(part / whole * 100).toFixed(0)}%`; +} + +function categoryTag(category: ReportedSpanCategory): string { + return CATEGORY_COLOR[category](`[${category}]`); +} + +function loopBusy(node: TraceResult): string | null { + const { elu } = node; + // a sync span never yields to the loop, so the number would be a trivial 100% + if (!elu || node.sync) { + return null; + } + const total = elu.idle + elu.active; + if (total < 1) { + return null; + } + return `loop-busy=${fmtPercent(elu.active, total)}`; +} + +function threadLabel(thread: number): string { + return thread === 0 ? 'main' : `worker#${thread}`; +} + +/** + * Collapse the middle of a breadcrumb so both ends survive: the task it belongs + * to and the span itself (plus as many of its nearest ancestors as fit). + */ +function fmtPath(path: string[], maxLength: number): string { + if (path.length < 3) { + return path.join(' › '); + } + const head = path[0]; + let out = path.at(-1)!; + for (let i = path.length - 2; i >= 1; i--) { + const candidate = `${path[i]} › ${out}`; + if (head.length + candidate.length + 8 > maxLength) { + return `${head} › … › ${out}`; + } + out = candidate; + } + return `${head} › ${out}`; +} + +/** Printable width of a string that may carry picocolors escapes */ +function visibleLength(s: string): number { + return stripVTControlCharacters(s).length; +} + +function pad(s: string, width: number, alignRight: boolean): string { + const fill = ' '.repeat(Math.max(0, width - visibleLength(s))); + return alignRight ? fill + s : s + fill; +} + +function table(header: string[], rows: string[][], rightAlignFrom = 1): string[] { + const widths = header.map((h, col) => Math.max(visibleLength(h), ...rows.map(r => visibleLength(r[col])))); + const fmtRow = (row: string[]) => row + .map((cell, col) => pad(cell, widths[col], col >= rightAlignFrom)) + .join(' '); + return [ + picocolors.bold(fmtRow(header)), + picocolors.dim(widths.map(w => '─'.repeat(w)).join(' ')), + ...rows.map(fmtRow) + ]; +} + +// --------------------------------------------------------------------------- +// Printing +// --------------------------------------------------------------------------- + +export function printTraceResult(traceResult: TraceResult) { + printTree( + normalizeTraceClock(traceResult), + (node, parentThread) => { + const parts: string[] = [node.name]; + + if (node.category) { + parts.push(categoryTag(node.category)); + } + + if (!isFinished(node)) { + parts.push(picocolors.red('(unfinished)')); + return parts.join(' '); + } + + parts.push(picocolors.bold(fmtMs(node.end - node.start))); + + if (node.children.length > 0) { + parts.push(picocolors.dim(`self=${fmtMs(selfTime(node))}`)); + } + + const busy = loopBusy(node); + if (busy) { + parts.push(picocolors.dim(busy)); + } + + if (node.thread !== parentThread) { + parts.push(picocolors.dim(`@${threadLabel(node.thread)}`)); + } + + return parts.join(' '); + } + ); +} + +function printTree(initialTree: TraceResult, printNode: (node: TraceResult, parentThread: number) => string) { + function printBranch(tree: TraceResult, branch: string, isGraphHead: boolean, isChildOfLastBranch: boolean, parentThread: number) { + const children = tree.children; + + let branchHead = ''; + + if (!isGraphHead) { + branchHead = children.length > 0 ? '┬ ' : '─ '; + } + + console.log(`${branch}${branchHead}${printNode(tree, parentThread)}`); + + let baseBranch = branch; + + if (!isGraphHead) { + baseBranch = branch.slice(0, -2) + (isChildOfLastBranch ? ' ' : '│ '); + } + + const nextBranch = `${baseBranch}├─`; + const lastBranch = `${baseBranch}└─`; + + children.forEach((child, index) => { + const last = children.length - 1 === index; + printBranch(child, last ? lastBranch : nextBranch, false, last, tree.thread); + }); + } + + printBranch(initialTree, '', true, false, initialTree.thread); +} + +/** Gantt-style overview of the top-level tasks on a shared timeline */ +export function printStats(rawStats: TraceResult[]): void { + const stats = rawStats.reduce((acc, trace) => { + const normalized = normalizeTraceClock(trace); + if (isFinished(normalized)) { + acc.push(normalized); + } + return acc; + }, []); + if (stats.length === 0) { + return; + } + + const longestTaskName = Math.max(...stats.map(i => i.name.length)); + const realStart = Math.min(...stats.map(i => i.start)); + const realEnd = Math.max(...stats.map(i => i.end)); + + const width = 100; + const statsStep = Math.max((realEnd - realStart) / width, 1); + + console.log(picocolors.bold('[timeline]'), `${fmtMs(realEnd - realStart)} wall, one column ≈ ${fmtMs(statsStep)}`); + + stats + .sort((a, b) => a.start - b.start) + .forEach((stat) => { + const offset = ((stat.start - realStart) / statsStep) | 0; + const length = Math.max(((stat.end - stat.start) / statsStep) | 0, 1); + console.log( + `[${stat.name}]${' '.repeat(longestTaskName - stat.name.length)}`, + ' '.repeat(offset) + '='.repeat(length), + picocolors.dim(fmtMs(stat.end - stat.start) + (stat.thread === 0 ? '' : ` @${threadLabel(stat.thread)}`)) + ); + }); +} + +export interface BuildResourceUsage { + /** Main thread event loop utilization delta over the whole build */ + elu?: SpanEventLoopUtilization, + /** `process.cpuUsage()` delta over the whole build, in microseconds. Covers every thread */ + cpu?: NodeJS.CpuUsage +} + +function printOverview(analysis: TraceAnalysis, usage: BuildResourceUsage | undefined) { + const parts = [`wall=${fmtMs(analysis.wall)}`]; + + if (usage?.elu) { + const { active, idle } = usage.elu; + parts.push(`main-loop-busy=${fmtMs(active)} (${fmtPercent(active, active + idle)})`, `main-loop-idle=${fmtMs(idle)}`); + } + if (usage?.cpu) { + const user = usage.cpu.user / 1000; + const system = usage.cpu.system / 1000; + const total = user + system; + parts.push( + `process-cpu=${fmtMs(total)} (user ${fmtMs(user)} / sys ${fmtMs(system)})`, + analysis.wall > 0 ? `cpu/wall=${(total / analysis.wall).toFixed(2)}x` : '' + ); + } + if (analysis.unfinishedSpans > 0) { + parts.push(picocolors.red(`unfinished-spans=${analysis.unfinishedSpans}`)); + } + + console.log(picocolors.bold('[build]'), parts.filter(Boolean).join(' ')); +} + +function printCategoryBreakdown(analysis: TraceAnalysis) { + const grandTotal = analysis.categories.reduce((acc, c) => acc + c.selfTotal, 0); + + console.log(); + console.log(picocolors.bold('[time by category]')); + console.log(picocolors.dim( + ' self = span time not covered by traced children, summed across concurrent spans (so it exceeds wall;\n' + + ' an async span on a busy event loop also includes time queued behind other work);\n' + + ' coverage = wall-clock during which at least one span of that category was in flight;\n' + + ' sync = the part of self that came from synchronous spans, i.e. guaranteed CPU on that thread' + )); + + const rows = analysis.categories.reduce((acc, c) => { + if (c.spans > 0) { + acc.push([ + CATEGORY_COLOR[c.category](c.category), + fmtMs(c.selfTotal), + fmtPercent(c.selfTotal, grandTotal), + fmtMs(c.coverage), + fmtPercent(c.coverage, analysis.wall), + String(c.spans), + fmtMs(c.selfOnMainThread), + fmtMs(c.selfOnWorkers), + fmtMs(c.selfSync) + ]); + } + return acc; + }, []); + + table(['category', 'self', 'share', 'coverage', 'of wall', 'spans', 'main', 'workers', 'sync'], rows) + .forEach(line => console.log(' ' + line)); +} + +function printTopSpans(analysis: TraceAnalysis) { + console.log(); + console.log(picocolors.bold('[top spans by self time, per category]')); + for (let i = 0, len = analysis.categories.length; i < len; i++) { + const stat = analysis.categories[i]; + if (stat.top.length === 0) { + continue; + } + console.log(' ' + categoryTag(stat.category)); + for (let j = 0, jlen = stat.top.length; j < jlen; j++) { + const span = stat.top[j]; + const extra: string[] = []; + if (span.node.children.length > 0) { + extra.push(`wall=${fmtMs(span.duration)}`); + } + const busy = loopBusy(span.node); + if (busy) { + extra.push(busy); + } + if (span.node.thread !== 0) { + extra.push(`@${threadLabel(span.node.thread)}`); + } + console.log( + ' ', + picocolors.bold(fmtMs(span.self).padStart(9)), + fmtPath(span.path, 110), + extra.length ? picocolors.dim(extra.join(' ')) : '' + ); + } + } + + console.log(); + console.log(picocolors.bold('[top spans by self time, overall]')); + for (let i = 0, len = analysis.topSpans.length; i < len; i++) { + const span = analysis.topSpans[i]; + console.log( + ' ', + picocolors.bold(fmtMs(span.self).padStart(9)), + categoryTag(span.category).padEnd(16), + fmtPath(span.path, 110) + ); + } +} + +function printTaskMatrix(analysis: TraceAnalysis) { + if (analysis.tasks.length === 0) { + return; + } + + console.log(); + console.log(picocolors.bold('[time by task × category]'), picocolors.dim('(self time of the task and all its descendants)')); + + const usedCategories = CATEGORY_ORDER.filter(c => analysis.tasks.some(t => t.byCategory[c] > 0)); + + const rows = analysis.tasks + .toSorted((a, b) => b.duration - a.duration) + .map((task) => { + const busy = task.node.elu ? fmtPercent(task.node.elu.active, task.node.elu.active + task.node.elu.idle) : 'n/a'; + return [ + task.node.name + (task.node.thread === 0 ? '' : picocolors.dim(` @${threadLabel(task.node.thread)}`)), + fmtMs(task.duration), + busy, + ...usedCategories.map(c => (task.byCategory[c] > 0 ? fmtMs(task.byCategory[c]) : picocolors.dim('·'))) + ]; + }); + + table(['task', 'wall', 'loop-busy', ...usedCategories], rows) + .forEach(line => console.log(' ' + line)); +} + +/** + * The full post-build report: every task's span tree, then the aggregate views + * (where does time go by category, which spans dominate, per-task breakdown and + * the shared timeline). + */ +export function printBuildReport(traces: TraceResult[], usage?: BuildResourceUsage) { + traces.forEach(printTraceResult); + + const analysis = analyzeTraces(traces); + + console.log(); + printOverview(analysis, usage); + printCategoryBreakdown(analysis); + printTopSpans(analysis); + printTaskMatrix(analysis); + console.log(); + printStats(traces); +} diff --git a/Build/trace/types.ts b/Build/trace/types.ts new file mode 100644 index 00000000..12cedad7 --- /dev/null +++ b/Build/trace/types.ts @@ -0,0 +1,68 @@ +import type { EventLoopUtilization } from 'node:perf_hooks'; + +export const SPAN_STATUS_START = 0; +export const SPAN_STATUS_END = 1; + +/** + * What a span spends its *self* time on (its own duration minus whatever its + * traced children cover). Unmarked spans are reported as "uncategorized" rather + * than inheriting from their parent, so gaps in instrumentation stay visible. + */ +export enum SpanCategory { + /** CPU-bound work on the current thread (parsing, trie ops, hashing, formatting) */ + Compute = 'compute', + /** Reading from the local filesystem */ + FsRead = 'fs-read', + /** Writing to the local filesystem */ + FsWrite = 'fs-write', + /** Fetching from the network (download, DNS, HTTP HEAD, ...) */ + Network = 'network', + /** Handing work to / waiting on a worker thread. Set automatically by traceWorkerChild */ + Worker = 'worker', + /** Waiting on another in-flight promise that is traced (or untraced) elsewhere */ + Wait = 'wait' +} + +export const UNCATEGORIZED = 'uncategorized'; +export type ReportedSpanCategory = SpanCategory | typeof UNCATEGORIZED; + +/** Delta of `performance.eventLoopUtilization()` across the span, in milliseconds */ +export interface SpanEventLoopUtilization { + idle: number, + active: number +} + +export interface TraceResult { + name: string, + category?: SpanCategory, + start: number, + end: number, + /** + * Event loop utilization of the thread that ran this span, over the span's + * lifetime. `active` is an upper bound of this span's own CPU time: on a shared + * event loop it also includes work done by concurrently running spans. + */ + elu?: SpanEventLoopUtilization, + /** + * Set when the span wrapped a synchronous function: its whole self time is + * CPU time on its thread, never queueing behind other work on the event loop. + */ + sync?: true, + /** `worker_threads.threadId` of the thread that created the span (0 = main thread) */ + thread: number, + /** + * `performance.timeOrigin` of the thread that produced this trace. Only set on + * the root returned by a task so traces produced on a worker thread can be + * shifted onto the main thread's clock before being compared with others. + */ + timeOrigin?: number, + children: TraceResult[] +} + +/** Pure data object — safe to transfer across Worker Thread boundaries. */ +export interface RawSpan { + traceResult: TraceResult, + status: typeof SPAN_STATUS_START | typeof SPAN_STATUS_END, + /** `performance.eventLoopUtilization()` sampled when the span started */ + eluStart?: EventLoopUtilization +}