log out module profile summary when profiling is enabled

This commit is contained in:
Tobias Koppers 2021-02-02 01:22:19 +01:00
parent bcfb3ad2c7
commit 3e1c7082d2
7 changed files with 462 additions and 55 deletions

View File

@ -183,6 +183,7 @@
"nwjs",
"redeclaration",
"kaios",
"parallelism",
"webassemblyjs",
"fsevents",

View File

@ -55,6 +55,7 @@ const StatsPrinter = require("./stats/StatsPrinter");
const { equals: arrayEquals } = require("./util/ArrayHelpers");
const AsyncQueue = require("./util/AsyncQueue");
const LazySet = require("./util/LazySet");
const { provide } = require("./util/MapHelpers");
const { cachedCleverMerge } = require("./util/cleverMerge");
const {
compareLocations,
@ -817,23 +818,29 @@ BREAKING CHANGE: Asset processing hooks in Compilation has been merged into a si
/** @type {CodeGenerationResults} */
this.codeGenerationResults = undefined;
/** @type {AsyncQueue<FactorizeModuleOptions, string, Module>} */
this.factorizeQueue = new AsyncQueue({
name: "factorize",
/** @type {AsyncQueue<Module, Module, Module>} */
this.processDependenciesQueue = new AsyncQueue({
name: "processDependencies",
parallelism: options.parallelism || 100,
processor: this._factorizeModule.bind(this)
processor: this._processModuleDependencies.bind(this)
});
/** @type {AsyncQueue<Module, string, Module>} */
this.addModuleQueue = new AsyncQueue({
name: "addModule",
parallelism: options.parallelism || 100,
parent: this.processDependenciesQueue,
getKey: module => module.identifier(),
processor: this._addModule.bind(this)
});
/** @type {AsyncQueue<FactorizeModuleOptions, string, Module>} */
this.factorizeQueue = new AsyncQueue({
name: "factorize",
parent: this.addModuleQueue,
processor: this._factorizeModule.bind(this)
});
/** @type {AsyncQueue<Module, Module, Module>} */
this.buildQueue = new AsyncQueue({
name: "build",
parallelism: options.parallelism || 100,
parent: this.factorizeQueue,
processor: this._buildModule.bind(this)
});
/** @type {AsyncQueue<Module, Module, Module>} */
@ -842,12 +849,6 @@ BREAKING CHANGE: Asset processing hooks in Compilation has been merged into a si
parallelism: options.parallelism || 100,
processor: this._rebuildModule.bind(this)
});
/** @type {AsyncQueue<Module, Module, Module>} */
this.processDependenciesQueue = new AsyncQueue({
name: "processDependencies",
parallelism: options.parallelism || 100,
processor: this._processModuleDependencies.bind(this)
});
/**
* Modules in value are building during the build of Module in key.
@ -1891,6 +1892,184 @@ BREAKING CHANGE: Asset processing hooks in Compilation has been merged into a si
}
finish(callback) {
if (this.profile) {
this.logger.time("finish module profiles");
const ParallelismFactorCalculator = require("./util/ParallelismFactorCalculator");
const p = new ParallelismFactorCalculator();
const moduleGraph = this.moduleGraph;
const modulesWithProfiles = new Map();
for (const module of this.modules) {
const profile = moduleGraph.getProfile(module);
if (!profile) continue;
modulesWithProfiles.set(module, profile);
p.range(
profile.buildingStartTime,
profile.buildingEndTime,
f => (profile.buildingParallelismFactor = f)
);
p.range(
profile.factoryStartTime,
profile.factoryEndTime,
f => (profile.factoryParallelismFactor = f)
);
p.range(
profile.integrationStartTime,
profile.integrationEndTime,
f => (profile.integrationParallelismFactor = f)
);
p.range(
profile.storingStartTime,
profile.storingEndTime,
f => (profile.storingParallelismFactor = f)
);
p.range(
profile.restoringStartTime,
profile.restoringEndTime,
f => (profile.restoringParallelismFactor = f)
);
if (profile.additionalFactoryTimes) {
for (const { start, end } of profile.additionalFactoryTimes) {
const influence = (end - start) / profile.additionalFactories;
p.range(
start,
end,
f =>
(profile.additionalFactoriesParallelismFactor += f * influence)
);
}
}
}
p.calculate();
const logger = this.getLogger("webpack.Compilation.ModuleProfile");
const logByValue = (value, msg) => {
if (value > 1000) {
logger.error(msg);
} else if (value > 500) {
logger.warn(msg);
} else if (value > 200) {
logger.info(msg);
} else if (value > 30) {
logger.log(msg);
} else {
logger.debug(msg);
}
};
const logNormalSummary = (category, getDuration, getParallelism) => {
let sum = 0;
let max = 0;
for (const [module, profile] of modulesWithProfiles) {
const p = getParallelism(profile);
const d = getDuration(profile);
if (d === 0 || p === 0) continue;
const t = d / p;
sum += t;
if (t <= 10) continue;
logByValue(
t,
` | ${Math.round(t)} ms${
p >= 1.1 ? ` (parallelism ${Math.round(p * 10) / 10})` : ""
} ${category} > ${module.readableIdentifier(this.requestShortener)}`
);
max = Math.max(max, t);
}
if (sum <= 10) return;
logByValue(
Math.max(sum / 10, max),
`${Math.round(sum)} ms ${category}`
);
};
const logByLoadersSummary = (category, getDuration, getParallelism) => {
const map = new Map();
for (const [module, profile] of modulesWithProfiles) {
const list = provide(
map,
module.type + "!" + module.identifier().replace(/(!|^)[^!]*$/, ""),
() => []
);
list.push({ module, profile });
}
let sum = 0;
let max = 0;
for (const [key, modules] of map) {
let innerSum = 0;
let innerMax = 0;
for (const { module, profile } of modules) {
const p = getParallelism(profile);
const d = getDuration(profile);
if (d === 0 || p === 0) continue;
const t = d / p;
innerSum += t;
if (t <= 10) continue;
logByValue(
t,
` | | ${Math.round(t)} ms${
p >= 1.1 ? ` (parallelism ${Math.round(p * 10) / 10})` : ""
} ${category} > ${module.readableIdentifier(
this.requestShortener
)}`
);
innerMax = Math.max(innerMax, t);
}
sum += innerSum;
if (innerSum <= 10) continue;
const idx = key.indexOf("!");
const loaders = key.slice(idx + 1);
const moduleType = key.slice(0, idx);
const t = Math.max(innerSum / 10, innerMax);
logByValue(
t,
` | ${Math.round(innerSum)} ms ${category} > ${
loaders
? `${
modules.length
} x ${moduleType} with ${this.requestShortener.shorten(
loaders
)}`
: `${modules.length} x ${moduleType}`
}`
);
max = Math.max(max, t);
}
if (sum <= 10) return;
logByValue(
Math.max(sum / 10, max),
`${Math.round(sum)} ms ${category}`
);
};
logNormalSummary(
"resolve to new modules",
p => p.factory,
p => p.factoryParallelismFactor
);
logNormalSummary(
"resolve to existing modules",
p => p.additionalFactories,
p => p.additionalFactoriesParallelismFactor
);
logNormalSummary(
"integrate modules",
p => p.restoring,
p => p.restoringParallelismFactor
);
logByLoadersSummary(
"build modules",
p => p.building,
p => p.buildingParallelismFactor
);
logNormalSummary(
"store modules",
p => p.storing,
p => p.storingParallelismFactor
);
logNormalSummary(
"restore modules",
p => p.restoring,
p => p.restoringParallelismFactor
);
this.logger.timeEnd("finish module profiles");
}
this.logger.time("finish modules");
const { modules } = this;
this.hooks.finishModules.callAsync(modules, err => {

View File

@ -8,12 +8,37 @@
class ModuleProfile {
constructor() {
this.startTime = Date.now();
this.factoryStartTime = 0;
this.factoryEndTime = 0;
this.factory = 0;
this.factoryParallelismFactor = 0;
this.restoringStartTime = 0;
this.restoringEndTime = 0;
this.restoring = 0;
this.restoringParallelismFactor = 0;
this.integrationStartTime = 0;
this.integrationEndTime = 0;
this.integration = 0;
this.integrationParallelismFactor = 0;
this.buildingStartTime = 0;
this.buildingEndTime = 0;
this.building = 0;
this.buildingParallelismFactor = 0;
this.storingStartTime = 0;
this.storingEndTime = 0;
this.storing = 0;
this.storingParallelismFactor = 0;
this.additionalFactoryTimes = undefined;
this.additionalFactories = 0;
this.additionalFactoriesParallelismFactor = 0;
/** @deprecated */
this.additionalIntegration = 0;
}
@ -70,10 +95,12 @@ class ModuleProfile {
* @returns {void}
*/
mergeInto(realProfile) {
if (this.factory > realProfile.additionalFactories)
realProfile.additionalFactories = this.factory;
if (this.integration > realProfile.additionalIntegration)
realProfile.additionalIntegration = this.integration;
realProfile.additionalFactories = this.factory;
(realProfile.additionalFactoryTimes =
realProfile.additionalFactoryTimes || []).push({
start: this.factoryStartTime,
end: this.factoryEndTime
});
}
}

103
lib/util/ArrayQueue.js Normal file
View File

@ -0,0 +1,103 @@
/*
MIT License http://www.opensource.org/licenses/mit-license.php
Author Tobias Koppers @sokra
*/
"use strict";
/**
* @template T
*/
class ArrayQueue {
/**
* @param {Iterable<T>=} items The initial elements.
*/
constructor(items) {
/** @private @type {T[]} */
this._list = items ? Array.from(items) : [];
/** @private @type {T[]} */
this._listReversed = [];
}
/**
* Returns the number of elements in this queue.
* @returns {number} The number of elements in this queue.
*/
get length() {
return this._list.length + this._listReversed.length;
}
/**
* Appends the specified element to this queue.
* @param {T} item The element to add.
* @returns {void}
*/
enqueue(item) {
this._list.push(item);
}
/**
* Retrieves and removes the head of this queue.
* @returns {T | undefined} The head of the queue of `undefined` if this queue is empty.
*/
dequeue() {
if (this._listReversed.length === 0) {
if (this._list.length === 0) return undefined;
if (this._list.length === 1) return this._list.pop();
if (this._list.length < 16) return this._list.shift();
const temp = this._listReversed;
this._listReversed = this._list;
this._listReversed.reverse();
this._list = temp;
}
return this._listReversed.pop();
}
/**
* Finds and removes an item
* @param {T} item the item
* @returns {void}
*/
delete(item) {
const i = this._list.indexOf(item);
if (i >= 0) {
this._list.splice(i, 1);
} else {
const i = this._listReversed.indexOf(item);
if (i >= 0) this._listReversed.splice(i, 1);
}
}
[Symbol.iterator]() {
let i = -1;
let reversed = false;
return {
next: () => {
if (!reversed) {
i++;
if (i < this._list.length) {
return {
done: false,
value: this._list[i]
};
}
reversed = true;
i = this._listReversed.length;
}
i--;
if (i < 0) {
return {
done: true,
value: undefined
};
}
return {
done: false,
value: this._listReversed[i]
};
}
};
}
}
module.exports = ArrayQueue;

View File

@ -6,6 +6,7 @@
"use strict";
const { SyncHook, AsyncSeriesHook } = require("tapable");
const ArrayQueue = require("./ArrayQueue");
const QUEUED_STATE = 0;
const PROCESSING_STATE = 1;
@ -51,23 +52,35 @@ class AsyncQueue {
/**
* @param {Object} options options object
* @param {string=} options.name name of the queue
* @param {number} options.parallelism how many items should be processed at once
* @param {number=} options.parallelism how many items should be processed at once
* @param {AsyncQueue<any, any, any>=} options.parent parent queue, which will have priority over this queue and with shared parallelism
* @param {function(T): K=} options.getKey extract key from item
* @param {function(T, Callback<R>): void} options.processor async function to process items
*/
constructor({ name, parallelism, processor, getKey }) {
constructor({ name, parallelism, parent, processor, getKey }) {
this._name = name;
this._parallelism = parallelism;
this._parallelism = parallelism || 1;
this._processor = processor;
this._getKey =
getKey || /** @type {(T) => K} */ (item => /** @type {any} */ (item));
/** @type {Map<K, AsyncQueueEntry<T, K, R>>} */
this._entries = new Map();
/** @type {AsyncQueueEntry<T, K, R>[]} */
this._queued = [];
/** @type {ArrayQueue<AsyncQueueEntry<T, K, R>>} */
this._queued = new ArrayQueue();
/** @type {AsyncQueue<any, any, any>[]} */
this._children = undefined;
this._activeTasks = 0;
this._willEnsureProcessing = false;
this._needProcessing = false;
this._stopped = false;
this._root = parent ? parent._root : this;
if (parent) {
if (this._root._children === undefined) {
this._root._children = [this];
} else {
this._root._children.push(this);
}
}
this.hooks = {
/** @type {AsyncSeriesHook<[T]>} */
@ -112,16 +125,18 @@ class AsyncQueue {
const newEntry = new AsyncQueueEntry(item, callback);
if (this._stopped) {
this.hooks.added.call(item);
this._activeTasks++;
this._root._activeTasks++;
process.nextTick(() =>
this._handleResult(newEntry, new Error("Queue was stopped"))
);
} else {
this._entries.set(key, newEntry);
this._queued.push(newEntry);
if (this._willEnsureProcessing === false) {
this._willEnsureProcessing = true;
setImmediate(this._ensureProcessing);
this._queued.enqueue(newEntry);
const root = this._root;
root._needProcessing = true;
if (root._willEnsureProcessing === false) {
root._willEnsureProcessing = true;
setImmediate(root._ensureProcessing);
}
this.hooks.added.call(item);
}
@ -137,10 +152,7 @@ class AsyncQueue {
const entry = this._entries.get(key);
this._entries.delete(key);
if (entry.state === QUEUED_STATE) {
const idx = this._queued.indexOf(entry);
if (idx >= 0) {
this._queued.splice(idx, 1);
}
this._queued.delete(entry);
}
}
@ -150,10 +162,11 @@ class AsyncQueue {
stop() {
this._stopped = true;
const queue = this._queued;
this._queued = [];
this._queued = new ArrayQueue();
const root = this._root;
for (const entry of queue) {
this._entries.delete(this._getKey(entry.item));
this._activeTasks++;
root._activeTasks++;
this._handleResult(entry, new Error("Queue was stopped"));
}
}
@ -162,11 +175,12 @@ class AsyncQueue {
* @returns {void}
*/
increaseParallelism() {
this._parallelism++;
const root = this._root;
root._parallelism++;
/* istanbul ignore next */
if (this._willEnsureProcessing === false && this._queued.length > 0) {
this._willEnsureProcessing = true;
setImmediate(this._ensureProcessing);
if (root._willEnsureProcessing === false && root._needProcessing) {
root._willEnsureProcessing = true;
setImmediate(root._ensureProcessing);
}
}
@ -174,7 +188,8 @@ class AsyncQueue {
* @returns {void}
*/
decreaseParallelism() {
this._parallelism--;
const root = this._root;
root._parallelism--;
}
/**
@ -211,13 +226,28 @@ class AsyncQueue {
* @returns {void}
*/
_ensureProcessing() {
while (this._activeTasks < this._parallelism && this._queued.length > 0) {
const entry = this._queued.pop();
while (this._activeTasks < this._parallelism) {
const entry = this._queued.dequeue();
if (entry === undefined) break;
this._activeTasks++;
entry.state = PROCESSING_STATE;
this._startProcessing(entry);
}
this._willEnsureProcessing = false;
if (this._queued.length > 0) return;
if (this._children !== undefined) {
for (const child of this._children) {
while (this._activeTasks < this._parallelism) {
const entry = child._queued.dequeue();
if (entry === undefined) break;
this._activeTasks++;
entry.state = PROCESSING_STATE;
child._startProcessing(entry);
}
if (child._queued.length > 0) return;
}
}
if (!this._willEnsureProcessing) this._needProcessing = false;
}
/**
@ -261,11 +291,12 @@ class AsyncQueue {
entry.callbacks = undefined;
entry.result = result;
entry.error = error;
this._activeTasks--;
if (this._willEnsureProcessing === false && this._queued.length > 0) {
this._willEnsureProcessing = true;
setImmediate(this._ensureProcessing);
const root = this._root;
root._activeTasks--;
if (root._willEnsureProcessing === false && root._needProcessing) {
root._willEnsureProcessing = true;
setImmediate(root._ensureProcessing);
}
if (inHandleResult++ > 3) {

View File

@ -0,0 +1,59 @@
/*
MIT License http://www.opensource.org/licenses/mit-license.php
Author Tobias Koppers @sokra
*/
"use strict";
const binarySearchBounds = require("../util/binarySearchBounds");
class ParallelismFactorCalculator {
constructor() {
this._rangePoints = [];
this._rangeCallbacks = [];
}
range(start, end, callback) {
if (start === end) return callback(1);
this._rangePoints.push(start);
this._rangePoints.push(end);
this._rangeCallbacks.push(callback);
}
calculate() {
const segments = Array.from(new Set(this._rangePoints)).sort((a, b) =>
a < b ? -1 : 1
);
const parallelism = segments.map(() => 0);
const rangeStartIndices = [];
for (let i = 0; i < this._rangePoints.length; i += 2) {
const start = this._rangePoints[i];
const end = this._rangePoints[i + 1];
let idx = binarySearchBounds.eq(segments, start);
rangeStartIndices.push(idx);
do {
parallelism[idx]++;
idx++;
} while (segments[idx] < end);
}
for (let i = 0; i < this._rangeCallbacks.length; i++) {
const start = this._rangePoints[i * 2];
const end = this._rangePoints[i * 2 + 1];
let idx = rangeStartIndices[i];
let sum = 0;
let totalDuration = 0;
let current = start;
do {
const p = parallelism[idx];
idx++;
const duration = segments[idx] - current;
totalDuration += duration;
current = segments[idx];
sum += p * duration;
} while (current < end);
this._rangeCallbacks[i](sum / totalDuration);
}
}
}
module.exports = ParallelismFactorCalculator;

31
types.d.ts vendored
View File

@ -1283,11 +1283,11 @@ declare class Compilation {
moduleGraph: ModuleGraph;
chunkGraph?: ChunkGraph;
codeGenerationResults: CodeGenerationResults;
factorizeQueue: AsyncQueue<FactorizeModuleOptions, string, Module>;
processDependenciesQueue: AsyncQueue<Module, Module, Module>;
addModuleQueue: AsyncQueue<Module, string, Module>;
factorizeQueue: AsyncQueue<FactorizeModuleOptions, string, Module>;
buildQueue: AsyncQueue<Module, Module, Module>;
rebuildQueue: AsyncQueue<Module, Module, Module>;
processDependenciesQueue: AsyncQueue<Module, Module, Module>;
/**
* Modules in value are building during the build of Module in key.
@ -5919,33 +5919,40 @@ declare interface ModulePathData {
}
declare abstract class ModuleProfile {
startTime: number;
factoryStartTime: number;
factoryEndTime: number;
factory: number;
factoryParallelismFactor: number;
restoringStartTime: number;
restoringEndTime: number;
restoring: number;
restoringParallelismFactor: number;
integrationStartTime: number;
integrationEndTime: number;
integration: number;
integrationParallelismFactor: number;
buildingStartTime: number;
buildingEndTime: number;
building: number;
buildingParallelismFactor: number;
storingStartTime: number;
storingEndTime: number;
storing: number;
storingParallelismFactor: number;
additionalFactoryTimes: any;
additionalFactories: number;
additionalFactoriesParallelismFactor: number;
additionalIntegration: number;
markFactoryStart(): void;
factoryStartTime?: number;
markFactoryEnd(): void;
factoryEndTime?: number;
markRestoringStart(): void;
restoringStartTime?: number;
markRestoringEnd(): void;
restoringEndTime?: number;
markIntegrationStart(): void;
integrationStartTime?: number;
markIntegrationEnd(): void;
integrationEndTime?: number;
markBuildingStart(): void;
buildingStartTime?: number;
markBuildingEnd(): void;
buildingEndTime?: number;
markStoringStart(): void;
storingStartTime?: number;
markStoringEnd(): void;
storingEndTime?: number;
/**
* Merge this profile into another one