From 482d23a56d1a2be1e48f20896b3872c2996b9d35 Mon Sep 17 00:00:00 2001 From: Marcin Szczepanski Date: Fri, 12 May 2023 13:03:58 +1000 Subject: [PATCH] Tracing (#8695) --- packages/core/core/package.json | 1 + packages/core/core/src/PackagerRunner.js | 19 ++ packages/core/core/src/Parcel.js | 5 + packages/core/core/src/ReporterRunner.js | 14 ++ packages/core/core/src/Transformation.js | 18 ++ packages/core/core/src/Validation.js | 8 + packages/core/core/src/applyRuntimes.js | 16 +- packages/core/core/src/assetUtils.js | 2 + .../core/src/requests/BundleGraphRequest.js | 43 ++++- .../core/core/src/requests/ConfigRequest.js | 9 + .../core/src/requests/ParcelBuildRequest.js | 4 + .../core/core/src/requests/PathRequest.js | 14 ++ .../core/src/requests/WriteBundleRequest.js | 9 + packages/core/core/src/resolveOptions.js | 1 + packages/core/core/src/types.js | 1 + packages/core/core/src/utils.js | 1 + packages/core/core/test/test-utils.js | 1 + .../core/integration-tests/test/tracing.js | 35 ++++ packages/core/parcel/package.json | 1 + packages/core/parcel/src/cli.js | 11 +- packages/core/profiler/package.json | 27 +++ .../src/SamplingProfiler.js} | 2 +- .../core/{workers => profiler}/src/Trace.js | 2 +- packages/core/profiler/src/Tracer.js | 163 ++++++++++++++++++ packages/core/profiler/src/index.js | 5 + packages/core/profiler/src/types.js | 10 ++ packages/core/profiler/test/Tracer.test.js | 78 +++++++++ packages/core/types/index.js | 76 +++++++- packages/core/workers/index.d.ts | 19 +- packages/core/workers/package.json | 2 +- packages/core/workers/src/Worker.js | 2 + packages/core/workers/src/WorkerFarm.js | 9 +- packages/core/workers/src/child.js | 16 +- packages/core/workers/src/index.js | 8 +- packages/reporters/tracer/package.json | 28 +++ .../reporters/tracer/src/TracerReporter.js | 87 ++++++++++ .../babel/src/BabelTransformer.js | 11 +- packages/transformers/babel/src/babel7.js | 26 ++- yarn.lock | 5 + 39 files changed, 760 insertions(+), 29 deletions(-) create mode 100644 packages/core/integration-tests/test/tracing.js create mode 100644 packages/core/profiler/package.json rename packages/core/{workers/src/Profiler.js => profiler/src/SamplingProfiler.js} (98%) rename packages/core/{workers => profiler}/src/Trace.js (98%) create mode 100644 packages/core/profiler/src/Tracer.js create mode 100644 packages/core/profiler/src/index.js create mode 100644 packages/core/profiler/src/types.js create mode 100644 packages/core/profiler/test/Tracer.test.js create mode 100644 packages/reporters/tracer/package.json create mode 100644 packages/reporters/tracer/src/TracerReporter.js diff --git a/packages/core/core/package.json b/packages/core/core/package.json index 57ef256f945..7d9a8567e93 100644 --- a/packages/core/core/package.json +++ b/packages/core/core/package.json @@ -34,6 +34,7 @@ "@parcel/logger": "2.8.3", "@parcel/package-manager": "2.8.3", "@parcel/plugin": "2.8.3", + "@parcel/profiler": "2.8.3", "@parcel/source-map": "^2.1.1", "@parcel/types": "2.8.3", "@parcel/utils": "2.8.3", diff --git a/packages/core/core/src/PackagerRunner.js b/packages/core/core/src/PackagerRunner.js index e31746f51f2..2015cb36d90 100644 --- a/packages/core/core/src/PackagerRunner.js +++ b/packages/core/core/src/PackagerRunner.js @@ -61,6 +61,7 @@ import {createBuildCache} from './buildCache'; import {getInvalidationId, getInvalidationHash} from './assetUtils'; import {optionsProxy} from './utils'; import {invalidateDevDeps} from './requests/DevDepRequest'; +import {tracer, PluginTracer} from '@parcel/profiler'; type Opts = {| config: ParcelConfig, @@ -275,6 +276,7 @@ export default class PackagerRunner { config: new PublicConfig(config, this.options), options: new PluginOptions(this.options), logger: new PluginLogger({origin: plugin.name}), + tracer: new PluginTracer({origin: plugin.name, category: 'loadConfig'}), }); bundleConfigs.set(plugin.name, config); } @@ -394,7 +396,11 @@ export default class PackagerRunner { let packager = await this.config.getPackager(bundle.name); let {name, resolveFrom, plugin} = packager; + let measurement; try { + measurement = tracer.createMeasurement(name, 'packaging', bundle.name, { + type: bundle.type, + }); return await plugin.package({ config: configs.get(name)?.result, bundleConfig: bundleConfigs.get(name)?.result, @@ -409,6 +415,7 @@ export default class PackagerRunner { }, options: this.pluginOptions, logger: new PluginLogger({origin: name}), + tracer: new PluginTracer({origin: name, category: 'package'}), getInlineBundleContents: async ( bundle: BundleType, bundleGraph: BundleGraphType, @@ -438,6 +445,7 @@ export default class PackagerRunner { }), }); } finally { + measurement && measurement.end(); // Add dev dependency for the packager. This must be done AFTER running it due to // the potential for lazy require() that aren't executed until the request runs. let devDepRequest = await createDevDependency( @@ -495,7 +503,13 @@ export default class PackagerRunner { }; for (let optimizer of optimizers) { + let measurement; try { + measurement = tracer.createMeasurement( + optimizer.name, + 'optimize', + bundle.name, + ); let next = await optimizer.plugin.optimize({ config: configs.get(optimizer.name)?.result, bundleConfig: bundleConfigs.get(optimizer.name)?.result, @@ -508,6 +522,10 @@ export default class PackagerRunner { }, options: this.pluginOptions, logger: new PluginLogger({origin: optimizer.name}), + tracer: new PluginTracer({ + origin: optimizer.name, + category: 'optimize', + }), }); optimized.type = next.type ?? optimized.type; @@ -521,6 +539,7 @@ export default class PackagerRunner { }), }); } finally { + measurement && measurement.end(); // Add dev dependency for the optimizer. This must be done AFTER running it due to // the potential for lazy require() that aren't executed until the request runs. let devDepRequest = await createDevDependency( diff --git a/packages/core/core/src/Parcel.js b/packages/core/core/src/Parcel.js index 240c8ad04cf..9adff5dccd7 100644 --- a/packages/core/core/src/Parcel.js +++ b/packages/core/core/src/Parcel.js @@ -41,6 +41,7 @@ import {Disposable} from '@parcel/events'; import {init as initSourcemaps} from '@parcel/source-map'; import {init as initHash} from '@parcel/hash'; import {toProjectPath} from './projectPath'; +import {tracer} from '@parcel/profiler'; registerCoreWithSerializer(); @@ -104,6 +105,7 @@ export default class Parcel { } else { this.#farm = createWorkerFarm({ shouldPatchConsole: resolvedOptions.shouldPatchConsole, + shouldTrace: resolvedOptions.shouldTrace, }); } @@ -257,6 +259,9 @@ export default class Parcel { if (options.shouldProfile) { await this.startProfiling(); } + if (options.shouldTrace) { + tracer.enable(); + } this.#reporterRunner.report({ type: 'buildStart', }); diff --git a/packages/core/core/src/ReporterRunner.js b/packages/core/core/src/ReporterRunner.js index a4887b98e6e..5bc7200122e 100644 --- a/packages/core/core/src/ReporterRunner.js +++ b/packages/core/core/src/ReporterRunner.js @@ -21,6 +21,7 @@ import logger, { } from '@parcel/logger'; import PluginOptions from './public/PluginOptions'; import BundleGraph from './BundleGraph'; +import {tracer, PluginTracer} from '@parcel/profiler'; type Opts = {| config: ParcelConfig, @@ -44,6 +45,7 @@ export default class ReporterRunner { this.pluginOptions = new PluginOptions(this.options); logger.onLog(event => this.report(event)); + tracer.onTrace(event => this.report(event)); bus.on('reporterEvent', this.eventHandler); instances.add(this); @@ -93,14 +95,26 @@ export default class ReporterRunner { } for (let reporter of this.reporters) { + let measurement; try { + // To avoid an infinite loop we don't measure trace events, as they'll + // result in another trace! + if (event.type !== 'trace') { + measurement = tracer.createMeasurement(reporter.name, 'reporter'); + } await reporter.plugin.report({ event, options: this.pluginOptions, logger: new PluginLogger({origin: reporter.name}), + tracer: new PluginTracer({ + origin: reporter.name, + category: 'reporter', + }), }); } catch (reportError) { INTERNAL_ORIGINAL_CONSOLE.error(reportError); + } finally { + measurement && measurement.end(); } } } catch (err) { diff --git a/packages/core/core/src/Transformation.js b/packages/core/core/src/Transformation.js index 7bfa9d4f332..e13b0762784 100644 --- a/packages/core/core/src/Transformation.js +++ b/packages/core/core/src/Transformation.js @@ -76,6 +76,7 @@ import { } from './projectPath'; import {invalidateOnFileCreateToInternal} from './utils'; import invariant from 'assert'; +import {tracer, PluginTracer} from '@parcel/profiler'; type GenerateFunc = (input: UncommittedAsset) => Promise; @@ -463,6 +464,12 @@ export default class Transformation { } try { + const measurement = tracer.createMeasurement( + transformer.name, + 'transform', + fromProjectPathRelative(initialAsset.value.filePath), + ); + let transformerResults = await this.runTransformer( pipeline, asset, @@ -473,6 +480,8 @@ export default class Transformation { this.parcelConfig, ); + measurement && measurement.end(); + for (let result of transformerResults) { if (result instanceof UncommittedAsset) { resultingAssets.push(result); @@ -739,6 +748,10 @@ export default class Transformation { parcelConfig: ParcelConfig, ): Promise<$ReadOnlyArray> { const logger = new PluginLogger({origin: transformerName}); + const tracer = new PluginTracer({ + origin: transformerName, + category: 'transform', + }); const resolve = async ( from: FilePath, @@ -794,6 +807,7 @@ export default class Transformation { ast: asset.ast, options: pipeline.pluginOptions, logger, + tracer, })) && asset.generate ) { @@ -814,6 +828,7 @@ export default class Transformation { options: pipeline.pluginOptions, resolve, logger, + tracer, }); if (ast) { asset.setAST(ast); @@ -830,6 +845,7 @@ export default class Transformation { options: pipeline.pluginOptions, resolve, logger, + tracer, }); let results = await normalizeAssets(this.options, transfomerResult); @@ -842,6 +858,7 @@ export default class Transformation { ast: asset.ast, options: pipeline.pluginOptions, logger, + tracer, }); asset.clearAST(); return Promise.resolve(generated); @@ -863,6 +880,7 @@ export default class Transformation { options: pipeline.pluginOptions, resolve, logger, + tracer, }); return Promise.all( diff --git a/packages/core/core/src/Validation.js b/packages/core/core/src/Validation.js index 3dcdcbcb29e..5f1acad7b03 100644 --- a/packages/core/core/src/Validation.js +++ b/packages/core/core/src/Validation.js @@ -16,6 +16,7 @@ import {Asset} from './public/Asset'; import PluginOptions from './public/PluginOptions'; import summarizeRequest from './summarizeRequest'; import {fromProjectPath, fromProjectPathRelative} from './projectPath'; +import {PluginTracer} from '@parcel/profiler'; export type ValidationOpts = {| config: ParcelConfig, @@ -66,6 +67,10 @@ export default class Validation { if (assets) { let plugin = this.allValidators[validatorName]; let validatorLogger = new PluginLogger({origin: validatorName}); + let validatorTracer = new PluginTracer({ + origin: validatorName, + category: 'validator', + }); let validatorResults: Array = []; try { // If the plugin supports the single-threading validateAll method, pass all assets to it. @@ -74,6 +79,7 @@ export default class Validation { assets: assets.map(asset => new Asset(asset)), options: pluginOptions, logger: validatorLogger, + tracer: validatorTracer, resolveConfigWithPath: ( configNames: Array, assetFilePath: string, @@ -98,6 +104,7 @@ export default class Validation { asset: publicAsset, options: pluginOptions, logger: validatorLogger, + tracer: validatorTracer, resolveConfig: (configNames: Array) => resolveConfig( this.options.inputFS, @@ -113,6 +120,7 @@ export default class Validation { options: pluginOptions, config, logger: validatorLogger, + tracer: validatorTracer, }); validatorResults.push(validatorResult); }), diff --git a/packages/core/core/src/applyRuntimes.js b/packages/core/core/src/applyRuntimes.js index de1530b9d03..4804a392aec 100644 --- a/packages/core/core/src/applyRuntimes.js +++ b/packages/core/core/src/applyRuntimes.js @@ -32,6 +32,7 @@ import {mergeEnvironments} from './Environment'; import createAssetGraphRequest from './requests/AssetGraphRequest'; import {createDevDependency, runDevDepRequest} from './requests/DevDepRequest'; import {toProjectPath, fromProjectPathRelative} from './projectPath'; +import {tracer, PluginTracer} from '@parcel/profiler'; type RuntimeConnection = {| bundle: InternalBundle, @@ -78,9 +79,16 @@ export default async function applyRuntimes({ for (let bundle of bundles) { for (let runtime of runtimes) { + let measurement; try { + const namedBundle = NamedBundle.get(bundle, bundleGraph, options); + measurement = tracer.createMeasurement( + runtime.name, + 'applyRuntime', + namedBundle.displayName, + ); let applied = await runtime.plugin.apply({ - bundle: NamedBundle.get(bundle, bundleGraph, options), + bundle: namedBundle, bundleGraph: new BundleGraph( bundleGraph, NamedBundle.get.bind(NamedBundle), @@ -89,6 +97,10 @@ export default async function applyRuntimes({ config: configs.get(runtime.name)?.result, options: pluginOptions, logger: new PluginLogger({origin: runtime.name}), + tracer: new PluginTracer({ + origin: runtime.name, + category: 'applyRuntime', + }), }); if (applied) { @@ -157,6 +169,8 @@ export default async function applyRuntimes({ origin: runtime.name, }), }); + } finally { + measurement && measurement.end(); } } } diff --git a/packages/core/core/src/assetUtils.js b/packages/core/core/src/assetUtils.js index a4961173688..6389e529c6f 100644 --- a/packages/core/core/src/assetUtils.js +++ b/packages/core/core/src/assetUtils.js @@ -38,6 +38,7 @@ import { } from './projectPath'; import {hashString} from '@parcel/hash'; import {BundleBehavior as BundleBehaviorMap} from './types'; +import {PluginTracer} from '@parcel/profiler'; type AssetOptions = {| id?: string, @@ -172,6 +173,7 @@ async function _generateFromAST(asset: CommittedAsset | UncommittedAsset) { ast, options: new PluginOptions(asset.options), logger: new PluginLogger({origin: pluginName}), + tracer: new PluginTracer({origin: pluginName, category: 'asset-generate'}), }); let mapBuffer = map?.toBuffer(); diff --git a/packages/core/core/src/requests/BundleGraphRequest.js b/packages/core/core/src/requests/BundleGraphRequest.js index 45feda04481..4fedc8d2b7f 100644 --- a/packages/core/core/src/requests/BundleGraphRequest.js +++ b/packages/core/core/src/requests/BundleGraphRequest.js @@ -54,6 +54,7 @@ import { toProjectPathUnsafe, } from '../projectPath'; import createAssetGraphRequest from './AssetGraphRequest'; +import {tracer, PluginTracer} from '@parcel/profiler'; type BundleGraphRequestInput = {| requestedAssetIds: Set, @@ -92,6 +93,7 @@ export default function createBundleGraphRequest( run: async input => { let {options, api, invalidateReason} = input; let {optionsRef, requestedAssetIds, signal} = input.input; + let measurement = tracer.createMeasurement('building'); let request = createAssetGraphRequest({ name: 'Main', entries: options.entries, @@ -105,7 +107,7 @@ export default function createBundleGraphRequest( force: options.shouldBuildLazily && requestedAssetIds.size > 0, }, ); - + measurement && measurement.end(); assertSignalNotAborted(signal); // If any subrequests are invalid (e.g. dev dep requests or config requests), @@ -133,13 +135,14 @@ export default function createBundleGraphRequest( let {devDeps, invalidDevDeps} = await getDevDepRequests(input.api); invalidateDevDeps(invalidDevDeps, input.options, parcelConfig); + let bundlingMeasurement = tracer.createMeasurement('bundling'); let builder = new BundlerRunner(input, parcelConfig, devDeps); let res: BundleGraphResult = await builder.bundle({ graph: assetGraph, changedAssets: changedAssets, assetRequests, }); - + bundlingMeasurement && bundlingMeasurement.end(); for (let [id, asset] of changedAssets) { res.changedAssets.set(id, asset); } @@ -268,7 +271,10 @@ class BundlerRunner { let internalBundleGraph; let logger = new PluginLogger({origin: name}); - + let tracer = new PluginTracer({ + origin: name, + category: 'bundle', + }); try { if (previousBundleGraphResult) { internalBundleGraph = previousBundleGraphResult.bundleGraph; @@ -298,16 +304,41 @@ class BundlerRunner { this.options, ); + let measurement; + let measurementFilename; + if (tracer.enabled) { + measurementFilename = graph + .getEntryAssets() + .map(asset => fromProjectPathRelative(asset.filePath)) + .join(', '); + measurement = tracer.createMeasurement( + plugin.name, + 'bundling:bundle', + measurementFilename, + ); + } + // this the normal bundle workflow (bundle, optimizing, run-times, naming) await bundler.bundle({ bundleGraph: mutableBundleGraph, config: this.configs.get(plugin.name)?.result, options: this.pluginOptions, logger, + tracer, }); + measurement && measurement.end(); + if (this.pluginOptions.mode === 'production') { + let optimizeMeasurement; try { + if (tracer.enabled) { + optimizeMeasurement = tracer.createMeasurement( + plugin.name, + 'bundling:optimize', + nullthrows(measurementFilename), + ); + } await bundler.optimize({ bundleGraph: mutableBundleGraph, config: this.configs.get(plugin.name)?.result, @@ -321,6 +352,7 @@ class BundlerRunner { }), }); } finally { + optimizeMeasurement && optimizeMeasurement.end(); await dumpGraphToGraphViz( // $FlowFixMe[incompatible-call] internalBundleGraph._graph, @@ -454,13 +486,16 @@ class BundlerRunner { ); for (let namer of namers) { + let measurement; try { + measurement = tracer.createMeasurement(namer.name, 'namer', bundle.id); let name = await namer.plugin.name({ bundle, bundleGraph, config: this.configs.get(namer.name)?.result, options: this.pluginOptions, logger: new PluginLogger({origin: namer.name}), + tracer: new PluginTracer({origin: namer.name, category: 'namer'}), }); if (name != null) { @@ -478,6 +513,8 @@ class BundlerRunner { origin: namer.name, }), }); + } finally { + measurement && measurement.end(); } } diff --git a/packages/core/core/src/requests/ConfigRequest.js b/packages/core/core/src/requests/ConfigRequest.js index f792e0c62c4..f07dde1d8b4 100644 --- a/packages/core/core/src/requests/ConfigRequest.js +++ b/packages/core/core/src/requests/ConfigRequest.js @@ -4,6 +4,7 @@ import type { Config as IConfig, PluginOptions as IPluginOptions, PluginLogger as IPluginLogger, + PluginTracer as IPluginTracer, NamedBundle as INamedBundle, BundleGraph as IBundleGraph, } from '@parcel/types'; @@ -24,12 +25,14 @@ import PublicConfig from '../public/Config'; import {optionsProxy} from '../utils'; import {getInvalidationHash} from '../assetUtils'; import {Hash} from '@parcel/hash'; +import {PluginTracer} from '@parcel/profiler'; export type PluginWithLoadConfig = { loadConfig?: ({| config: IConfig, options: IPluginOptions, logger: IPluginLogger, + tracer: IPluginTracer, |}) => Async, ... }; @@ -39,6 +42,7 @@ export type PluginWithBundleConfig = { config: IConfig, options: IPluginOptions, logger: IPluginLogger, + tracer: IPluginTracer, |}) => Async, loadBundleConfig?: ({| bundle: INamedBundle, @@ -46,6 +50,7 @@ export type PluginWithBundleConfig = { config: IConfig, options: IPluginOptions, logger: IPluginLogger, + tracer: IPluginTracer, |}) => Async, ... }; @@ -80,6 +85,10 @@ export async function loadPluginConfig( }), ), logger: new PluginLogger({origin: loadedPlugin.name}), + tracer: new PluginTracer({ + origin: loadedPlugin.name, + category: 'loadConfig', + }), }); } catch (e) { throw new ThrowableDiagnostic({ diff --git a/packages/core/core/src/requests/ParcelBuildRequest.js b/packages/core/core/src/requests/ParcelBuildRequest.js index 41546184a6b..20616954ced 100644 --- a/packages/core/core/src/requests/ParcelBuildRequest.js +++ b/packages/core/core/src/requests/ParcelBuildRequest.js @@ -21,6 +21,8 @@ import IBundleGraph from '../public/BundleGraph'; import {NamedBundle} from '../public/Bundle'; import {assetFromValue} from '../public/Asset'; +import {tracer} from '@parcel/profiler'; + type ParcelBuildRequestInput = {| optionsRef: SharedReference, requestedAssetIds: Set, @@ -91,12 +93,14 @@ async function run({input, api, options}) { ), }); + let packagingMeasurement = tracer.createMeasurement('packaging'); let writeBundlesRequest = createWriteBundlesRequest({ bundleGraph, optionsRef, }); let bundleInfo = await api.runRequest(writeBundlesRequest); + packagingMeasurement && packagingMeasurement.end(); assertSignalNotAborted(signal); return {bundleGraph, bundleInfo, changedAssets, assetRequests}; diff --git a/packages/core/core/src/requests/PathRequest.js b/packages/core/core/src/requests/PathRequest.js index 743964cf975..e00bd99c5a0 100644 --- a/packages/core/core/src/requests/PathRequest.js +++ b/packages/core/core/src/requests/PathRequest.js @@ -46,6 +46,7 @@ import { invalidateDevDeps, runDevDepRequest, } from './DevDepRequest'; +import {tracer, PluginTracer} from '@parcel/profiler'; export type PathRequest = {| id: string, @@ -275,15 +276,26 @@ export class ResolverRunner { let invalidateOnFileChange = []; let invalidateOnEnvChange = []; for (let resolver of resolvers) { + let measurement; try { + measurement = tracer.createMeasurement( + resolver.name, + 'resolve', + specifier, + ); let result = await resolver.plugin.resolve({ specifier, pipeline, dependency: dep, options: this.pluginOptions, logger: new PluginLogger({origin: resolver.name}), + tracer: new PluginTracer({ + origin: resolver.name, + category: 'resolver', + }), config: this.configs.get(resolver.name)?.result, }); + measurement && measurement.end(); if (result) { if (result.meta) { @@ -375,6 +387,8 @@ export class ResolverRunner { break; } finally { + measurement && measurement.end(); + // Add dev dependency for the resolver. This must be done AFTER running it due to // the potential for lazy require() that aren't executed until the request runs. let devDepRequest = await createDevDependency( diff --git a/packages/core/core/src/requests/WriteBundleRequest.js b/packages/core/core/src/requests/WriteBundleRequest.js index 80f1f84ed09..379d7fc2357 100644 --- a/packages/core/core/src/requests/WriteBundleRequest.js +++ b/packages/core/core/src/requests/WriteBundleRequest.js @@ -38,6 +38,7 @@ import { } from './DevDepRequest'; import ParcelConfig from '../ParcelConfig'; import ThrowableDiagnostic, {errorToDiagnostic} from '@parcel/diagnostic'; +import {PluginTracer, tracer} from '@parcel/profiler'; const BOUNDARY_LENGTH = HASH_REF_PREFIX.length + 32 - 1; @@ -243,11 +244,18 @@ async function runCompressor( devDeps: Map, api: RunAPI, ) { + let measurement; try { + measurement = tracer.createMeasurement( + compressor.name, + 'compress', + path.relative(options.projectRoot, filePath), + ); let res = await compressor.plugin.compress({ stream, options: new PluginOptions(options), logger: new PluginLogger({origin: compressor.name}), + tracer: new PluginTracer({origin: compressor.name, category: 'compress'}), }); if (res != null) { @@ -272,6 +280,7 @@ async function runCompressor( }), }); } finally { + measurement && measurement.end(); // Add dev deps for compressor plugins AFTER running them, to account for lazy require(). let devDepRequest = await createDevDependency( { diff --git a/packages/core/core/src/resolveOptions.js b/packages/core/core/src/resolveOptions.js index 561e88aad87..fbae0e7e486 100644 --- a/packages/core/core/src/resolveOptions.js +++ b/packages/core/core/src/resolveOptions.js @@ -151,6 +151,7 @@ export default async function resolveOptions( : false, shouldDisableCache: initialOptions.shouldDisableCache ?? false, shouldProfile: initialOptions.shouldProfile ?? false, + shouldTrace: initialOptions.shouldTrace ?? false, cacheDir, entries: entries.map(e => toProjectPath(projectRoot, e)), targets: initialOptions.targets, diff --git a/packages/core/core/src/types.js b/packages/core/core/src/types.js index 9dcd169f564..f199d323f7d 100644 --- a/packages/core/core/src/types.js +++ b/packages/core/core/src/types.js @@ -275,6 +275,7 @@ export type ParcelOptions = {| logLevel: LogLevel, projectRoot: FilePath, shouldProfile: boolean, + shouldTrace: boolean, shouldPatchConsole: boolean, detailedReport?: ?DetailedReportOptions, diff --git a/packages/core/core/src/utils.js b/packages/core/core/src/utils.js index 8de07de3b64..f60ad4645b6 100644 --- a/packages/core/core/src/utils.js +++ b/packages/core/core/src/utils.js @@ -103,6 +103,7 @@ const ignoreOptions = new Set([ 'shouldAutoInstall', 'logLevel', 'shouldProfile', + 'shouldTrace', 'shouldPatchConsole', 'projectRoot', 'additionalReporters', diff --git a/packages/core/core/test/test-utils.js b/packages/core/core/test/test-utils.js index 29caf4900c8..a02a1175b93 100644 --- a/packages/core/core/test/test-utils.js +++ b/packages/core/core/test/test-utils.js @@ -31,6 +31,7 @@ export const DEFAULT_OPTIONS: ParcelOptions = { env: {}, shouldDisableCache: false, shouldProfile: false, + shouldTrace: false, inputFS, outputFS, cache, diff --git a/packages/core/integration-tests/test/tracing.js b/packages/core/integration-tests/test/tracing.js new file mode 100644 index 00000000000..1c9a9b72493 --- /dev/null +++ b/packages/core/integration-tests/test/tracing.js @@ -0,0 +1,35 @@ +// @flow strict-local +import assert from 'assert'; +import path from 'path'; +import {distDir, bundle, outputFS} from '@parcel/test-utils'; + +describe('tracing', function () { + it('should produce a trace', async function () { + await bundle( + path.join(__dirname, '/integration/typescript-jsx/index.tsx'), + { + shouldTrace: true, + targets: { + default: {distDir}, + }, + additionalReporters: [ + { + packageName: '@parcel/reporter-tracer', + resolveFrom: __dirname, + }, + ], + outputFS, + }, + ); + + const files = outputFS.readdirSync(__dirname); + const profileFile = files.find(file => file.startsWith('parcel-trace')); + assert(profileFile !== null); + const content = await outputFS.readFile( + path.join(__dirname, profileFile), + 'utf8', + ); + const profileContent = JSON.parse(content + ']'); // Traces don't contain a closing ] as an optimisation for partial writes + assert(profileContent.length > 0); + }); +}); diff --git a/packages/core/parcel/package.json b/packages/core/parcel/package.json index 602121f204f..5e623fe49cd 100644 --- a/packages/core/parcel/package.json +++ b/packages/core/parcel/package.json @@ -28,6 +28,7 @@ "@parcel/fs": "2.8.3", "@parcel/logger": "2.8.3", "@parcel/package-manager": "2.8.3", + "@parcel/reporter-tracer": "2.8.3", "@parcel/reporter-cli": "2.8.3", "@parcel/reporter-dev-server": "2.8.3", "@parcel/utils": "2.8.3", diff --git a/packages/core/parcel/src/cli.js b/packages/core/parcel/src/cli.js index d46676c4445..e04b060d01c 100755 --- a/packages/core/parcel/src/cli.js +++ b/packages/core/parcel/src/cli.js @@ -86,7 +86,8 @@ const commonOptions = { '--dist-dir ': 'output directory to write to when unspecified by targets', '--no-autoinstall': 'disable autoinstall', - '--profile': 'enable build profiling', + '--profile': 'enable sampling build profiling', + '--trace': 'enable build tracing', '-V, --version': 'output the version number', '--detailed-report [count]': [ 'print the asset timings and sizes in the build report', @@ -462,6 +463,13 @@ async function normalizeOptions( })), ]; + if (command.trace) { + additionalReporters.unshift({ + packageName: '@parcel/reporter-tracer', + resolveFrom: __filename, + }); + } + let mode = command.name() === 'build' ? 'production' : 'development'; return { shouldDisableCache: command.cache === false, @@ -475,6 +483,7 @@ async function normalizeOptions( shouldAutoInstall: command.autoinstall ?? true, logLevel: command.logLevel, shouldProfile: command.profile, + shouldTrace: command.trace, shouldBuildLazily: command.lazy, shouldBundleIncrementally: process.env.PARCEL_INCREMENTAL_BUNDLING === 'false' ? false : true, diff --git a/packages/core/profiler/package.json b/packages/core/profiler/package.json new file mode 100644 index 00000000000..a652099cd9a --- /dev/null +++ b/packages/core/profiler/package.json @@ -0,0 +1,27 @@ +{ + "name": "@parcel/profiler", + "version": "2.8.3", + "description": "Blazing fast, zero configuration web application bundler", + "license": "MIT", + "publishConfig": { + "access": "public" + }, + "funding": { + "type": "opencollective", + "url": "https://opencollective.com/parcel" + }, + "repository": { + "type": "git", + "url": "https://github.com/parcel-bundler/parcel.git" + }, + "main": "lib/index.js", + "source": "src/index.js", + "engines": { + "node": ">= 12.0.0" + }, + "dependencies": { + "@parcel/diagnostic": "2.8.3", + "@parcel/events": "2.8.3", + "chrome-trace-event": "^1.0.2" + } +} diff --git a/packages/core/workers/src/Profiler.js b/packages/core/profiler/src/SamplingProfiler.js similarity index 98% rename from packages/core/workers/src/Profiler.js rename to packages/core/profiler/src/SamplingProfiler.js index 925de032195..0828e174fc2 100644 --- a/packages/core/workers/src/Profiler.js +++ b/packages/core/profiler/src/SamplingProfiler.js @@ -37,7 +37,7 @@ type PositionTickInfo = {| ticks: number, |}; -export default class Profiler { +export default class SamplingProfiler { session: Session; startProfiling(): Promise { diff --git a/packages/core/workers/src/Trace.js b/packages/core/profiler/src/Trace.js similarity index 98% rename from packages/core/workers/src/Trace.js rename to packages/core/profiler/src/Trace.js index e9530d06f36..fecfc762f86 100644 --- a/packages/core/workers/src/Trace.js +++ b/packages/core/profiler/src/Trace.js @@ -1,5 +1,5 @@ // @flow -import type {Profile} from './Profiler'; +import type {Profile} from './SamplingProfiler'; import type {Writable} from 'stream'; import {Tracer} from 'chrome-trace-event'; diff --git a/packages/core/profiler/src/Tracer.js b/packages/core/profiler/src/Tracer.js new file mode 100644 index 00000000000..9ddff5ffb45 --- /dev/null +++ b/packages/core/profiler/src/Tracer.js @@ -0,0 +1,163 @@ +// @flow strict-local + +import type { + TraceEvent, + IDisposable, + PluginTracer as IPluginTracer, +} from '@parcel/types'; +import type { + TraceMeasurement as ITraceMeasurement, + TraceMeasurementData, +} from './types'; +import {ValueEmitter} from '@parcel/events'; + +// $FlowFixMe +import {performance as _performance} from 'perf_hooks'; + +let tid; +try { + tid = require('worker_threads').threadId; +} catch { + tid = 0; +} + +const performance: Performance = _performance; +const pid = process.pid; + +class TraceMeasurement implements ITraceMeasurement { + #active /* boolean */ = true; + #name /* string */; + #pid /* number */; + #tid /* number */; + #start /* number */; + #data /* any */; + constructor(tracer: Tracer, name, pid, tid, data) { + this.#name = name; + this.#pid = pid; + this.#tid = tid; + this.#start = performance.now(); + this.#data = data; + } + + end() { + if (!this.#active) return; + const duration = performance.now() - this.#start; + tracer.trace({ + type: 'trace', + name: this.#name, + pid: this.#pid, + tid: this.#tid, + duration, + ts: this.#start, + ...this.#data, + }); + this.#active = false; + } +} + +export default class Tracer { + #traceEmitter /* ValueEmitter */ = new ValueEmitter(); + + #enabled /* boolean */ = false; + + onTrace(cb: (event: TraceEvent) => mixed): IDisposable { + return this.#traceEmitter.addListener(cb); + } + + async wrap(name: string, fn: () => mixed): Promise { + let measurement = this.createMeasurement(name); + try { + await fn(); + } finally { + measurement && measurement.end(); + } + } + + createMeasurement( + name: string, + category?: string = 'Core', + argumentName?: string, + otherArgs?: {[key: string]: mixed}, + ): ITraceMeasurement | null { + if (!this.enabled) return null; + + // We create `args` in a fairly verbose way to avoid object + // allocation where not required. + let args: {[key: string]: mixed}; + if (typeof argumentName === 'string') { + args = {name: argumentName}; + } + if (typeof otherArgs === 'object') { + if (typeof args == 'undefined') { + args = {}; + } + for (const [k, v] of Object.entries(otherArgs)) { + args[k] = v; + } + } + + const data: TraceMeasurementData = { + categories: [category], + args, + }; + + return new TraceMeasurement(this, name, pid, tid, data); + } + + get enabled(): boolean { + return this.#enabled; + } + + enable(): void { + this.#enabled = true; + } + + disable(): void { + this.#enabled = false; + } + + trace(event: TraceEvent): void { + if (!this.#enabled) return; + this.#traceEmitter.emit(event); + } +} + +export const tracer: Tracer = new Tracer(); + +type TracerOpts = {| + origin: string, + category: string, +|}; +export class PluginTracer implements IPluginTracer { + /** @private */ + origin: string; + + /** @private */ + category: string; + + /** @private */ + constructor(opts: TracerOpts) { + this.origin = opts.origin; + this.category = opts.category; + } + + get enabled(): boolean { + return tracer.enabled; + } + + createMeasurement( + name: string, + category?: string, + argumentName?: string, + otherArgs?: {[key: string]: mixed}, + ): ITraceMeasurement | null { + return tracer.createMeasurement( + name, + `${this.category}:${this.origin}${ + typeof category === 'string' ? `:${category}` : '' + }`, + argumentName, + otherArgs, + ); + } +} diff --git a/packages/core/profiler/src/index.js b/packages/core/profiler/src/index.js new file mode 100644 index 00000000000..f21ca6283ce --- /dev/null +++ b/packages/core/profiler/src/index.js @@ -0,0 +1,5 @@ +// @flow +export {default as SamplingProfiler} from './SamplingProfiler'; +export {default as Trace} from './Trace'; +export {tracer, PluginTracer} from './Tracer'; +export type {TraceMeasurement, TraceMeasurementData} from './types'; diff --git a/packages/core/profiler/src/types.js b/packages/core/profiler/src/types.js new file mode 100644 index 00000000000..031fdbeda84 --- /dev/null +++ b/packages/core/profiler/src/types.js @@ -0,0 +1,10 @@ +// @flow + +export interface TraceMeasurement { + end(): void; +} + +export type TraceMeasurementData = {| + +categories: string[], + +args?: {[key: string]: mixed}, +|}; diff --git a/packages/core/profiler/test/Tracer.test.js b/packages/core/profiler/test/Tracer.test.js new file mode 100644 index 00000000000..3dd68fcfc91 --- /dev/null +++ b/packages/core/profiler/test/Tracer.test.js @@ -0,0 +1,78 @@ +import {tracer, PluginTracer} from '../src/Tracer'; +import sinon from 'sinon'; +import assert from 'assert'; + +describe('Tracer', () => { + let onTrace; + let traceDisposable; + beforeEach(() => { + onTrace = sinon.spy(); + traceDisposable = tracer.onTrace(onTrace); + tracer.enable(); + }); + afterEach(() => { + traceDisposable.dispose(); + }); + + it('returns no measurement when disabled', () => { + tracer.disable(); + const measurement = tracer.createMeasurement('test'); + assert(measurement == null); + assert(onTrace.notCalled); + }); + it('emits a basic trace event', () => { + const measurement = tracer.createMeasurement('test'); + measurement.end(); + sinon.assert.calledWith( + onTrace, + sinon.match({ + type: 'trace', + name: 'test', + args: undefined, + duration: sinon.match.number, + }), + ); + }); + it('emits a complex trace event', () => { + const measurement = tracer.createMeasurement('test', 'myPlugin', 'aaargh', { + extra: 'data', + }); + measurement.end(); + sinon.assert.calledWith( + onTrace, + sinon.match({ + type: 'trace', + name: 'test', + categories: ['myPlugin'], + args: {extra: 'data', name: 'aaargh'}, + duration: sinon.match.number, + }), + ); + }); + it('calling end twice on measurment should be a no-op', () => { + const measurement = tracer.createMeasurement('test'); + measurement.end(); + measurement.end(); + sinon.assert.calledOnce(onTrace); + }); + + describe('PluginTracer', () => { + it('emits events with proper origin/category', () => { + const pluginTracer = new PluginTracer({ + origin: 'origin', + category: 'cat', + }); + const measurement = pluginTracer.createMeasurement('test', 'customCat'); + measurement.end(); + sinon.assert.calledWith( + onTrace, + sinon.match({ + type: 'trace', + name: 'test', + categories: ['cat:origin:customCat'], + duration: sinon.match.number, + }), + ); + }); + }); +}); diff --git a/packages/core/types/index.js b/packages/core/types/index.js index c625e1e3083..50cb98f4a73 100644 --- a/packages/core/types/index.js +++ b/packages/core/types/index.js @@ -13,6 +13,7 @@ import type { import type {Cache} from '@parcel/cache'; import type {AST as _AST, ConfigResult as _ConfigResult} from './unsafe'; +import type {TraceMeasurement} from '@parcel/profiler'; /** Plugin-specific AST, any */ export type AST = _AST; @@ -298,6 +299,7 @@ export type InitialParcelOptions = {| +shouldAutoInstall?: boolean, +logLevel?: LogLevel, +shouldProfile?: boolean, + +shouldTrace?: boolean, +shouldPatchConsole?: boolean, +shouldBuildLazily?: boolean, +shouldBundleIncrementally?: boolean, @@ -1029,6 +1031,7 @@ export type DedicatedThreadValidator = {| resolveConfigWithPath: ResolveConfigWithPathFn, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}) => Async>, |}; @@ -1042,12 +1045,14 @@ export type MultiThreadValidator = {| config: ConfigResult | void, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}) => Async, getConfig?: ({| asset: Asset, resolveConfig: ResolveConfigFn, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}) => Async, |}; @@ -1065,12 +1070,14 @@ export type Transformer = {| config: Config, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}) => Promise | ConfigType, /** Whether an AST from a previous transformer can be reused (to prevent double-parsing) */ canReuseAST?: ({| ast: AST, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}) => boolean, /** Parse the contents into an ast */ parse?: ({| @@ -1079,6 +1086,7 @@ export type Transformer = {| resolve: ResolveFn, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}) => Async, /** Transform the asset and/or add new assets */ transform({| @@ -1087,6 +1095,7 @@ export type Transformer = {| resolve: ResolveFn, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}): Async>, /** * Do some processing after the transformation @@ -1098,6 +1107,7 @@ export type Transformer = {| resolve: ResolveFn, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}) => Async>, /** Stringify the AST */ generate?: ({| @@ -1105,6 +1115,7 @@ export type Transformer = {| ast: AST, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}) => Async, |}; @@ -1576,12 +1587,14 @@ export type Bundler = {| config: Config, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}) => Promise | ConfigType, bundle({| bundleGraph: MutableBundleGraph, config: ConfigType, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}): Async, optimize({| bundleGraph: MutableBundleGraph, @@ -1599,6 +1612,7 @@ export type Namer = {| config: Config, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}) => Promise | ConfigType, /** Return a filename/-path for bundle or nullish to leave it to the next namer plugin. */ name({| @@ -1607,6 +1621,7 @@ export type Namer = {| config: ConfigType, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}): Async, |}; @@ -1633,6 +1648,7 @@ export type Runtime = {| config: Config, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}) => Promise | ConfigType, apply({| bundle: NamedBundle, @@ -1640,6 +1656,7 @@ export type Runtime = {| config: ConfigType, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}): Async>, |}; @@ -1651,6 +1668,7 @@ export type Packager = {| config: Config, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}) => Async, loadBundleConfig?: ({| bundle: NamedBundle, @@ -1658,12 +1676,14 @@ export type Packager = {| config: Config, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}) => Async, package({| bundle: NamedBundle, bundleGraph: BundleGraph, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, config: ConfigType, bundleConfig: BundleConfigType, getInlineBundleContents: ( @@ -1682,6 +1702,7 @@ export type Optimizer = {| config: Config, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}) => Async, loadBundleConfig?: ({| bundle: NamedBundle, @@ -1689,6 +1710,7 @@ export type Optimizer = {| config: Config, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}) => Async, optimize({| bundle: NamedBundle, @@ -1697,6 +1719,7 @@ export type Optimizer = {| map: ?SourceMap, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, config: ConfigType, bundleConfig: BundleConfigType, getSourceMapReference: (map: ?SourceMap) => Async, @@ -1711,6 +1734,7 @@ export type Compressor = {| stream: Readable, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}): Async = {| config: Config, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}) => Promise | ConfigType, resolve({| dependency: Dependency, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, specifier: FilePath, pipeline: ?string, config: ConfigType, @@ -1896,6 +1922,23 @@ export type ValidationEvent = {| +filePath: FilePath, |}; +/** + * A trace event has occured. + * Loosely modeled on Chrome's Trace Event format: https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview + * + * @section reporter + */ +export type TraceEvent = {| + +type: 'trace', + +ts: number, + +duration: number, + +name: string, + +tid: number, + +pid: number, + +categories: string[], + +args?: {[key: string]: mixed}, +|}; + /** * @section reporter */ @@ -1907,7 +1950,8 @@ export type ReporterEvent = | BuildFailureEvent | WatchStartEvent | WatchEndEvent - | ValidationEvent; + | ValidationEvent + | TraceEvent; /** * @section reporter @@ -1917,6 +1961,7 @@ export type Reporter = {| event: ReporterEvent, options: PluginOptions, logger: PluginLogger, + tracer: PluginTracer, |}): Async, |}; @@ -1931,3 +1976,32 @@ export interface IDisposable { export type AsyncSubscription = {| unsubscribe(): Promise, |}; + +export interface PluginTracer { + /** Returns whether the tracer is enabled. Use this to avoid possibly expensive calculations + * of arguments to `createMeasurement` - for example if you need to determine the entry of a bundle to pass it + * in as the argumentName, you would only do this if the tracer is enabled. + */ + +enabled: boolean; + + /** + * Creates a new trace measurement with the specified name. This name should reflect the current plugin or + * function being executed (for example, the name of a Babel transform). The category will default to the name of your plugin, + * however it should be set to reflect the type of operation (for example, for a hypothetical operation + * to find CSS in an asset within a Compiled plugin you might set this to find_css). + * + * If this is an operation that executes multiple times on different things - whether that's assets, bundles, or + * otherwise - specify the name of the context object in argumentName. + * + * otherArgs can be used for specifying any other key/value pairs + * that should be written to the trace. + * + * For example: tracer.createMeasurement('compiled', 'find_css', path.relative(options.projecRoot, asset.filePath), { meta: 'data' }) + */ + createMeasurement( + name: string, + category?: string, + argumentName?: string, + otherArgs?: {[key: string]: mixed}, + ): TraceMeasurement | null; +} diff --git a/packages/core/workers/index.d.ts b/packages/core/workers/index.d.ts index f081fa34285..b18f9d73acc 100644 --- a/packages/core/workers/index.d.ts +++ b/packages/core/workers/index.d.ts @@ -3,14 +3,15 @@ import {FilePath} from '@parcel/types'; type BackendType = 'process' | 'threads'; export type FarmOptions = { - maxConcurrentWorkers: number, - maxConcurrentCallsPerWorker: number, - forcedKillTime: number, - useLocalWorker: boolean, - warmWorkers: boolean, - workerPath?: FilePath, - backend: BackendType, - shouldPatchConsole?: boolean, + maxConcurrentWorkers: number; + maxConcurrentCallsPerWorker: number; + forcedKillTime: number; + useLocalWorker: boolean; + warmWorkers: boolean; + workerPath?: FilePath; + backend: BackendType; + shouldPatchConsole?: boolean; + shouldTrace?: boolean; }; declare class WorkerFarm { @@ -19,4 +20,4 @@ declare class WorkerFarm { end(): Promise; } -export default WorkerFarm; +export default WorkerFarm; diff --git a/packages/core/workers/package.json b/packages/core/workers/package.json index fa9ffe21b33..dada22c37c1 100644 --- a/packages/core/workers/package.json +++ b/packages/core/workers/package.json @@ -23,9 +23,9 @@ "dependencies": { "@parcel/diagnostic": "2.8.3", "@parcel/logger": "2.8.3", + "@parcel/profiler": "2.8.3", "@parcel/types": "2.8.3", "@parcel/utils": "2.8.3", - "chrome-trace-event": "^1.0.2", "nullthrows": "^1.1.1" }, "peerDependencies": { diff --git a/packages/core/workers/src/Worker.js b/packages/core/workers/src/Worker.js index e13f67b7e6a..ce98cde5933 100644 --- a/packages/core/workers/src/Worker.js +++ b/packages/core/workers/src/Worker.js @@ -23,6 +23,7 @@ type WorkerOpts = {| forcedKillTime: number, backend: BackendType, shouldPatchConsole?: boolean, + shouldTrace?: boolean, sharedReferences: $ReadOnlyMap, |}; @@ -108,6 +109,7 @@ export default class Worker extends EventEmitter { forkModule, { shouldPatchConsole: !!this.options.shouldPatchConsole, + shouldTrace: !!this.options.shouldTrace, }, ], retries: 0, diff --git a/packages/core/workers/src/WorkerFarm.js b/packages/core/workers/src/WorkerFarm.js index 37ef1f150d2..8822ba1736d 100644 --- a/packages/core/workers/src/WorkerFarm.js +++ b/packages/core/workers/src/WorkerFarm.js @@ -26,8 +26,7 @@ import cpuCount from './cpuCount'; import Handle from './Handle'; import {child} from './childState'; import {detectBackend} from './backend'; -import Profiler from './Profiler'; -import Trace from './Trace'; +import {SamplingProfiler, Trace} from '@parcel/profiler'; import fs from 'fs'; import logger from '@parcel/logger'; @@ -44,6 +43,7 @@ export type FarmOptions = {| workerPath?: FilePath, backend: BackendType, shouldPatchConsole?: boolean, + shouldTrace?: boolean, |}; type WorkerModule = {| @@ -77,7 +77,7 @@ export default class WorkerFarm extends EventEmitter { sharedReferences: Map = new Map(); sharedReferencesByValue: Map = new Map(); serializedSharedReferences: Map = new Map(); - profiler: ?Profiler; + profiler: ?SamplingProfiler; constructor(farmOptions: $Shape = {}) { super(); @@ -239,6 +239,7 @@ export default class WorkerFarm extends EventEmitter { forcedKillTime: this.options.forcedKillTime, backend: this.options.backend, shouldPatchConsole: this.options.shouldPatchConsole, + shouldTrace: this.options.shouldTrace, sharedReferences: this.sharedReferences, }); @@ -516,7 +517,7 @@ export default class WorkerFarm extends EventEmitter { ); } - this.profiler = new Profiler(); + this.profiler = new SamplingProfiler(); promises.push(this.profiler.startProfiling()); await Promise.all(promises); diff --git a/packages/core/workers/src/child.js b/packages/core/workers/src/child.js index e38027e5c1a..2e276dad752 100644 --- a/packages/core/workers/src/child.js +++ b/packages/core/workers/src/child.js @@ -18,7 +18,7 @@ import Logger, {patchConsole, unpatchConsole} from '@parcel/logger'; import ThrowableDiagnostic, {anyToDiagnostic} from '@parcel/diagnostic'; import {deserialize} from '@parcel/core'; import bus from './bus'; -import Profiler from './Profiler'; +import {SamplingProfiler, tracer} from '@parcel/profiler'; import _Handle from './Handle'; // The import of './Handle' should really be imported eagerly (with @babel/plugin-transform-modules-commonjs's lazy mode). @@ -37,8 +37,9 @@ export class Child { responseId: number = 0; responseQueue: Map = new Map(); loggerDisposable: IDisposable; + tracerDisposable: IDisposable; child: ChildImpl; - profiler: ?Profiler; + profiler: ?SamplingProfiler; handles: Map = new Map(); sharedReferences: Map = new Map(); sharedReferencesByValue: Map = new Map(); @@ -56,6 +57,10 @@ export class Child { this.loggerDisposable = Logger.onLog(event => { bus.emit('logEvent', event); }); + // .. and do the same for trace events + this.tracerDisposable = tracer.onTrace(event => { + bus.emit('traceEvent', event); + }); } workerApi: {| @@ -141,12 +146,16 @@ export class Child { unpatchConsole(); } + if (childOptions.shouldTrace) { + tracer.enable(); + } + result = responseFromContent(await this.childInit(moduleName, child)); } catch (e) { result = errorResponseFromError(e); } } else if (method === 'startProfile') { - this.profiler = new Profiler(); + this.profiler = new SamplingProfiler(); try { result = responseFromContent(await this.profiler.startProfiling()); } catch (e) { @@ -289,6 +298,7 @@ export class Child { handleEnd(): void { this.loggerDisposable.dispose(); + this.tracerDisposable.dispose(); } createReverseHandle(fn: (...args: Array) => mixed): Handle { diff --git a/packages/core/workers/src/index.js b/packages/core/workers/src/index.js index 21fcfb1b53f..f737ba2df4a 100644 --- a/packages/core/workers/src/index.js +++ b/packages/core/workers/src/index.js @@ -1,9 +1,10 @@ // @flow -import type {LogEvent} from '@parcel/types'; +import type {TraceEvent, LogEvent} from '@parcel/types'; import invariant from 'assert'; import WorkerFarm from './WorkerFarm'; import Logger from '@parcel/logger'; import bus from './bus'; +import {tracer} from '@parcel/profiler'; if (!WorkerFarm.isWorker()) { // Forward all logger events originating from workers into the main process @@ -29,6 +30,11 @@ if (!WorkerFarm.isWorker()) { throw new Error('Unknown log level'); } }); + + // Forward all trace events originating from workers into the main process + bus.on('traceEvent', (e: TraceEvent) => { + tracer.trace(e); + }); } export default WorkerFarm; diff --git a/packages/reporters/tracer/package.json b/packages/reporters/tracer/package.json new file mode 100644 index 00000000000..a105a32353c --- /dev/null +++ b/packages/reporters/tracer/package.json @@ -0,0 +1,28 @@ +{ + "name": "@parcel/reporter-tracer", + "version": "2.8.3", + "license": "MIT", + "publishConfig": { + "access": "public" + }, + "funding": { + "type": "opencollective", + "url": "https://opencollective.com/parcel" + }, + "repository": { + "type": "git", + "url": "https://github.com/parcel-bundler/parcel.git" + }, + "main": "lib/TracerReporter.js", + "source": "src/TracerReporter.js", + "engines": { + "node": ">= 12.0.0", + "parcel": "^2.8.3" + }, + "dependencies": { + "@parcel/plugin": "2.8.3", + "@parcel/utils": "2.8.3", + "chrome-trace-event": "^1.0.3", + "nullthrows": "^1.1.1" + } +} diff --git a/packages/reporters/tracer/src/TracerReporter.js b/packages/reporters/tracer/src/TracerReporter.js new file mode 100644 index 00000000000..c04d78b0238 --- /dev/null +++ b/packages/reporters/tracer/src/TracerReporter.js @@ -0,0 +1,87 @@ +// @flow +import invariant from 'assert'; +import nullthrows from 'nullthrows'; +import path from 'path'; +import {Reporter} from '@parcel/plugin'; +import {Tracer} from 'chrome-trace-event'; + +// We need to maintain some state here to ensure we write to the same output, there should only be one +// instance of this reporter (this gets asserted below) +let tracer; +let writeStream = null; + +function millisecondsToMicroseconds(milliseconds: number) { + return Math.floor(milliseconds * 1000); +} + +// TODO: extract this to utils as it's also used in packages/core/workers/src/WorkerFarm.js +function getTimeId() { + let now = new Date(); + return ( + String(now.getFullYear()) + + String(now.getMonth() + 1).padStart(2, '0') + + String(now.getDate()).padStart(2, '0') + + '-' + + String(now.getHours()).padStart(2, '0') + + String(now.getMinutes()).padStart(2, '0') + + String(now.getSeconds()).padStart(2, '0') + ); +} + +export default (new Reporter({ + report({event, options, logger}) { + let filename; + let filePath; + switch (event.type) { + case 'buildStart': + invariant(tracer == null, 'Tracer multiple initialisation'); + tracer = new Tracer(); + filename = `parcel-trace-${getTimeId()}.json`; + filePath = path.join(options.projectRoot, filename); + invariant( + writeStream == null, + 'Trace write stream multiple initialisation', + ); + logger.info({ + message: `Writing trace to ${filename}. See https://parceljs.org/features/profiling/#analysing-traces for more information on working with traces.`, + }); + writeStream = options.outputFS.createWriteStream(filePath); + nullthrows(tracer).pipe(nullthrows(writeStream)); + break; + case 'trace': + // Due to potential race conditions at the end of the build, we ignore any trace events that occur + // after we've closed the write stream. + if (tracer === null) return; + + tracer.completeEvent({ + name: event.name, + cat: event.categories, + args: event.args, + ts: millisecondsToMicroseconds(event.ts), + dur: millisecondsToMicroseconds(event.duration), + tid: event.tid, + pid: event.pid, + }); + break; + case 'buildSuccess': + case 'buildFailure': + nullthrows(tracer).flush(); + // We explicitly trigger `end` on the writeStream for the trace, then we need to wait for + // the `close` event before resolving the promise this report function returns to ensure + // that the file has been properly closed and moved from it's temp location before Parcel + // shuts down. + return new Promise((resolve, reject) => { + nullthrows(writeStream).once('close', err => { + writeStream = null; + tracer = null; + if (err) { + reject(err); + } else { + resolve(); + } + }); + nullthrows(writeStream).end(); + }); + } + }, +}): Reporter); diff --git a/packages/transformers/babel/src/BabelTransformer.js b/packages/transformers/babel/src/BabelTransformer.js index dbddccb0094..45e6e3c2152 100644 --- a/packages/transformers/babel/src/BabelTransformer.js +++ b/packages/transformers/babel/src/BabelTransformer.js @@ -17,7 +17,7 @@ export default (new Transformer({ return ast.type === 'babel' && semver.satisfies(ast.version, '^7.0.0'); }, - async transform({asset, config, logger, options}) { + async transform({asset, config, logger, options, tracer}) { try { if (config?.config) { if ( @@ -30,9 +30,16 @@ export default (new Transformer({ logger, babelOptions: config, additionalPlugins: asset.meta.babelPlugins, + tracer, }); } else { - await babel7({asset, options, logger, babelOptions: config}); + await babel7({ + asset, + options, + logger, + babelOptions: config, + tracer, + }); } } diff --git a/packages/transformers/babel/src/babel7.js b/packages/transformers/babel/src/babel7.js index 8d4ddee0548..ef613ffd036 100644 --- a/packages/transformers/babel/src/babel7.js +++ b/packages/transformers/babel/src/babel7.js @@ -4,6 +4,7 @@ import type { MutableAsset, AST, PluginOptions, + PluginTracer, PluginLogger, } from '@parcel/types'; import typeof * as BabelCore from '@babel/core'; @@ -25,12 +26,13 @@ type Babel7TransformOptions = {| logger: PluginLogger, babelOptions: any, additionalPlugins?: Array, + tracer: PluginTracer, |}; export default async function babel7( opts: Babel7TransformOptions, ): Promise { - let {asset, options, babelOptions, additionalPlugins = []} = opts; + let {asset, options, babelOptions, additionalPlugins = [], tracer} = opts; const babelCore: BabelCore = await options.packageManager.require( '@babel/core', asset.filePath, @@ -74,6 +76,28 @@ export default async function babel7( }, }; + if (tracer.enabled) { + config.wrapPluginVisitorMethod = ( + key: string, + nodeType: string, + fn: Function, + ) => { + return function () { + let pluginKey = key; + if (pluginKey.startsWith(options.projectRoot)) { + pluginKey = path.relative(options.projectRoot, pluginKey); + } + const measurement = tracer.createMeasurement( + pluginKey, + nodeType, + path.relative(options.projectRoot, asset.filePath), + ); + fn.apply(this, arguments); + measurement && measurement.end(); + }; + }; + } + let ast = await asset.getAST(); let res; if (ast) { diff --git a/yarn.lock b/yarn.lock index 06653018781..0fd3900935f 100644 --- a/yarn.lock +++ b/yarn.lock @@ -3957,6 +3957,11 @@ chrome-trace-event@^1.0.2: dependencies: tslib "^1.9.0" +chrome-trace-event@^1.0.3: + version "1.0.3" + resolved "https://packages.atlassian.com/api/npm/npm-remote/chrome-trace-event/-/chrome-trace-event-1.0.3.tgz#1015eced4741e15d06664a957dbbf50d041e26ac" + integrity sha512-p3KULyQg4S7NIHixdwbGX+nFHkoBiA4YQmyWtjb8XngSKV124nJmRysgAeujbUVb15vh+RvFUfCPqU7rXk+hZg== + ci-info@^2.0.0: version "2.0.0" resolved "https://registry.yarnpkg.com/ci-info/-/ci-info-2.0.0.tgz#67a9e964be31a51e15e5010d58e6f12834002f46"