Skip to content

Commit

Permalink
refactor: performance timers for node.js and browser (#4340)
Browse files Browse the repository at this point in the history
* refactor: performance timers for node.js and browser

* simplify, add return types

* refactor: replace object with array

* refactor: replace fn.apply with spread

* refactor: use map

* nit

* export performance object

* type fixes

* fix browser perf test, add comment

* export entire process object

* remove type assertion in rollup.config

* remove comment

* extract interface

* check for performance object in alternative environments

Co-authored-by: Lukas Taegert-Atkinson <lukastaegert@users.noreply.github.com>
  • Loading branch information
dnalborczyk and lukastaegert committed Jan 14, 2022
1 parent edca64e commit 7c47283
Show file tree
Hide file tree
Showing 10 changed files with 99 additions and 80 deletions.
10 changes: 10 additions & 0 deletions browser/performance.ts
@@ -0,0 +1,10 @@
const global =
typeof globalThis !== 'undefined' ? globalThis : typeof window !== 'undefined' ? window : {};

export default 'performance' in global
? performance
: {
now(): 0 {
return 0;
}
};
11 changes: 11 additions & 0 deletions browser/process.ts
@@ -0,0 +1,11 @@
interface MemoryUsage {
heapUsed: 0;
}

export default {
memoryUsage(): MemoryUsage {
return {
heapUsed: 0
};
}
};
34 changes: 20 additions & 14 deletions build-plugins/replace-browser-modules.ts
@@ -1,29 +1,35 @@
import path from 'path';
import { Plugin } from 'rollup';
import { dirname, join, resolve } from 'path';
import type { Plugin } from 'rollup';

const ID_CRYPTO = path.resolve('src/utils/crypto');
const ID_FS = path.resolve('src/utils/fs');
const ID_HOOKACTIONS = path.resolve('src/utils/hookActions');
const ID_PATH = path.resolve('src/utils/path');
const ID_RESOLVEID = path.resolve('src/utils/resolveId');
const ID_CRYPTO = resolve('src/utils/crypto');
const ID_FS = resolve('src/utils/fs');
const ID_HOOKACTIONS = resolve('src/utils/hookActions');
const ID_PATH = resolve('src/utils/path');
const ID_PERFORMANCE = resolve('src/utils/performance');
const ID_PROCESS = resolve('src/utils/process');
const ID_RESOLVEID = resolve('src/utils/resolveId');

export default function replaceBrowserModules(): Plugin {
return {
name: 'replace-browser-modules',
resolveId: (source, importee) => {
resolveId(source, importee) {
if (importee && source[0] === '.') {
const resolved = path.join(path.dirname(importee), source);
const resolved = join(dirname(importee), source);
switch (resolved) {
case ID_CRYPTO:
return path.resolve('browser/crypto.ts');
return resolve('browser/crypto.ts');
case ID_FS:
return path.resolve('browser/fs.ts');
return resolve('browser/fs.ts');
case ID_HOOKACTIONS:
return path.resolve('browser/hookActions.ts');
return resolve('browser/hookActions.ts');
case ID_PATH:
return path.resolve('browser/path.ts');
return resolve('browser/path.ts');
case ID_PERFORMANCE:
return resolve('browser/performance.ts');
case ID_PROCESS:
return resolve('browser/process.ts');
case ID_RESOLVEID:
return path.resolve('browser/resolveId.ts');
return resolve('browser/resolveId.ts');
}
}
}
Expand Down
11 changes: 6 additions & 5 deletions rollup.config.ts
@@ -1,4 +1,4 @@
import fs from 'fs';
import { readFileSync } from 'fs';
import path from 'path';
import alias from '@rollup/plugin-alias';
import commonjs from '@rollup/plugin-commonjs';
Expand All @@ -18,7 +18,7 @@ import pkg from './package.json';

const commitHash = (function () {
try {
return fs.readFileSync('.commithash', 'utf-8');
return readFileSync('.commithash', 'utf-8');
} catch {
return 'unknown';
}
Expand Down Expand Up @@ -90,8 +90,10 @@ export default (command: Record<string, unknown>): RollupOptions | RollupOptions
'fs',
'fsevents',
'module',
'path',
'os',
'path',
'perf_hooks',
'process',
'stream',
'url',
'util'
Expand Down Expand Up @@ -125,8 +127,7 @@ export default (command: Record<string, unknown>): RollupOptions | RollupOptions
...nodePlugins,
addCliEntry(),
esmDynamicImport(),
// TODO this relied on an unpublished type update
(!command.configTest && collectLicenses()) as Plugin
!command.configTest && collectLicenses()
],
strictDeprecations: true,
treeshake
Expand Down
4 changes: 2 additions & 2 deletions src/utils/collapseSourcemaps.ts
Expand Up @@ -49,7 +49,7 @@ class Link {
const sources: string[] = [];
const sourcesContent: string[] = [];
const names: string[] = [];
const nameIndexMap: Map<string, number> = new Map();
const nameIndexMap = new Map<string, number>();

const mappings = [];

Expand Down Expand Up @@ -147,7 +147,7 @@ class Link {
}

function getLinkMap(warn: WarningHandler) {
return function linkMap(source: Source | Link, map: DecodedSourceMapOrMissing) {
return function linkMap(source: Source | Link, map: DecodedSourceMapOrMissing): Link {
if (map.mappings) {
return new Link(map, [source]);
}
Expand Down
2 changes: 1 addition & 1 deletion src/utils/crypto.ts
@@ -1,3 +1,3 @@
import { createHash as cryptoCreateHash, Hash } from 'crypto';
import { createHash as cryptoCreateHash, type Hash } from 'crypto';

export const createHash = (): Hash => cryptoCreateHash('sha256');
1 change: 1 addition & 0 deletions src/utils/performance.ts
@@ -0,0 +1 @@
export { performance as default } from 'perf_hooks';
1 change: 1 addition & 0 deletions src/utils/process.ts
@@ -0,0 +1 @@
export { default } from 'process';
100 changes: 42 additions & 58 deletions src/utils/timers.ts
@@ -1,39 +1,18 @@
import { InputOptions, Plugin, SerializedTimings } from '../rollup/types';

type StartTime = [number, number];
import performance from './performance';
import process from './process';

interface Timer {
memory: number;
startMemory: number;
startTime: StartTime;
startTime: number;
time: number;
totalMemory: number;
}

interface Timers {
[label: string]: Timer;
}

const NOOP = (): void => {};
let getStartTime = (): StartTime => [0, 0];
let getElapsedTime: (previous: StartTime) => number = () => 0;
let getMemory: () => number = () => 0;
let timers: Timers = {};

const normalizeHrTime = (time: [number, number]): number => time[0] * 1e3 + time[1] / 1e6;

function setTimeHelpers(): void {
if (typeof process !== 'undefined' && typeof process.hrtime === 'function') {
getStartTime = process.hrtime.bind(process);
getElapsedTime = previous => normalizeHrTime(process.hrtime(previous));
} else if (typeof performance !== 'undefined' && typeof performance.now === 'function') {
getStartTime = () => [performance.now(), 0];
getElapsedTime = previous => performance.now() - previous[0];
}
if (typeof process !== 'undefined' && typeof process.memoryUsage === 'function') {
getMemory = () => process.memoryUsage().heapUsed;
}
}

let timers = new Map<string, Timer>();

function getPersistedLabel(label: string, level: number): string {
switch (level) {
Expand All @@ -50,82 +29,87 @@ function getPersistedLabel(label: string, level: number): string {

function timeStartImpl(label: string, level = 3): void {
label = getPersistedLabel(label, level);
if (!timers.hasOwnProperty(label)) {
timers[label] = {

const startMemory = process.memoryUsage().heapUsed;
const startTime = performance.now();

const timer = timers.get(label);

if (timer === undefined) {
timers.set(label, {
memory: 0,
startMemory: undefined as never,
startTime: undefined as never,
startMemory,
startTime,
time: 0,
totalMemory: 0
};
});
} else {
timer.startMemory = startMemory;
timer.startTime = startTime;
}
const currentMemory = getMemory();
timers[label].startTime = getStartTime();
timers[label].startMemory = currentMemory;
}

function timeEndImpl(label: string, level = 3): void {
label = getPersistedLabel(label, level);
if (timers.hasOwnProperty(label)) {
const currentMemory = getMemory();
timers[label].time += getElapsedTime(timers[label].startTime);
timers[label].totalMemory = Math.max(timers[label].totalMemory, currentMemory);
timers[label].memory += currentMemory - timers[label].startMemory;

const timer = timers.get(label);

if (timer !== undefined) {
const currentMemory = process.memoryUsage().heapUsed;
timer.memory += currentMemory - timer.startMemory;
timer.time += performance.now() - timer.startTime;
timer.totalMemory = Math.max(timer.totalMemory, currentMemory);
}
}

export function getTimings(): SerializedTimings {
const newTimings: SerializedTimings = {};
for (const [label, { time, memory, totalMemory }] of Object.entries(timers)) {

for (const [label, { memory, time, totalMemory }] of timers) {
newTimings[label] = [time, memory, totalMemory];
}
return newTimings;
}

export let timeStart: (label: string, level?: number) => void = NOOP,
timeEnd: (label: string, level?: number) => void = NOOP;
export let timeStart: (label: string, level?: number) => void = NOOP;
export let timeEnd: (label: string, level?: number) => void = NOOP;

const TIMED_PLUGIN_HOOKS: { [hook: string]: boolean } = {
load: true,
resolveDynamicImport: true,
resolveId: true,
transform: true
};
const TIMED_PLUGIN_HOOKS = ['load', 'resolveDynamicImport', 'resolveId', 'transform'] as const;

function getPluginWithTimers(plugin: any, index: number): Plugin {
const timedPlugin: { [hook: string]: any } = {};
const timedPlugin: Pick<Plugin, typeof TIMED_PLUGIN_HOOKS[number]> = {};

for (const hook of Object.keys(plugin)) {
if (TIMED_PLUGIN_HOOKS[hook] === true) {
for (const hook of TIMED_PLUGIN_HOOKS) {
if (hook in plugin) {
let timerLabel = `plugin ${index}`;
if (plugin.name) {
timerLabel += ` (${plugin.name})`;
}
timerLabel += ` - ${hook}`;
timedPlugin[hook] = function (...args: unknown[]) {
timeStart(timerLabel, 4);
let result = plugin[hook].apply(this === timedPlugin ? plugin : this, args);
const result = plugin[hook](...args);

This comment has been minimized.

Copy link
@SuperOleg39

SuperOleg39 Jan 18, 2022

Contributor

Hi, @dnalborczyk!

We have a custom plugin with context usage in transform method, here is simple example:

{
  transform(code) {
    const ast = this.parse(code, {});
    ...
  }
}

After rollup update, plugin context is unavailable and we catch error with this stacktrace:

 | TypeError: this.parse is not a function
 |     at Object.transform (/home/runner/work/tramvai/tramvai/tools/build/lib/plugins/require.js:23:30)
 |     at Object.timedPlugin.<computed> (/home/runner/work/tramvai/tramvai/node_modules/rollup/dist/shared/rollup.js:12211:44)
 |     at /home/runner/work/tramvai/tramvai/node_modules/rollup/dist/shared/rollup.js:22771:37
 |     at processTicksAndRejections (internal/process/task_queues.js:95:5) {
 |   code: 'PLUGIN_ERROR',
 |   plugin: 'add-require-chunk',
 |   hook: 'transform',
 |   id: '/home/runner/work/tramvai/tramvai/packages/tramvai/experiments/src/index.ts',
 |   watchFiles: [
 |     '/home/runner/work/tramvai/tramvai/packages/tramvai/experiments/src/index.ts'
 |   ]
 | }

Is there a important reason to remove apply call?

This comment has been minimized.

Copy link
@lukastaegert

lukastaegert Jan 18, 2022

Author Member

Totally overlooked this in the review. I will have a look why this did not turn a test red, it definitely should have.

Update: Ah, of course we do not use timers in tests ...

This comment has been minimized.

Copy link
@SuperOleg39

SuperOleg39 Jan 18, 2022

Contributor

If i understand right, this error caused only with perf: true parameter, looks like it is not easy to maintain all test cases for both perf values)

Also, year ago have another problem with utils/timer - #4010 (comment) :))

Maybe at future will be better to merge performance timings logic in main code, and remove this flag?

This comment has been minimized.

Copy link
@lukastaegert

lukastaegert Jan 18, 2022

Author Member

There are actually two tests, adds-timings-to-bundle and adds-timings-to-bundle-when-codesplitting, they just do not use the plugin api. As wrapping plugin hooks is one of the main things perf: true does, maybe as a first step we should just extend those tests a little with some consistency checks that plugins work and have a valid context.

This comment has been minimized.

Copy link
@dnalborczyk

dnalborczyk Jan 18, 2022

Author Contributor

makes more sense now why the this arg is even needed. replacing it with spread args was an eslint suggestion, which in this particular case didn't apply. I'm thinking instead of creating a new [timer-plugin] object it might be better to wrap the prototype methods instead, so the this args always point to the correct this.

@lukastaegert I'll have a look.

This comment has been minimized.

Copy link
@dnalborczyk

dnalborczyk Jan 18, 2022

Author Contributor

on a different note, looking at the code again, reminded me of another question I had. the sync and async label should start at the same time, meaning currently the async label is starting too late, as the function has already been started to execute at that point in time.

This comment has been minimized.

Copy link
@lukastaegert

lukastaegert Jan 19, 2022

Author Member

No, that was intended as for an async hook, you have BOTH sync and async time measured. So the actual time is the sum of both times. In any case, I have long wondered if we should not get rid of the async time altogether as that one is not helpful at all because it does not measure time spent in the plugin but just the time between triggering and resolving. But as many modules are loaded in parallel, even a fast hook can get slow async timings because other async code may be executed in between. And the sum of those times can far exceed the total build time.
If we want to improve something here, I would suggest to remove the second async timer altogether but for async hooks, extend the label e.g. (excluding async time) to signal there is more stuff that was not measured.

This comment has been minimized.

Copy link
@SuperOleg39

SuperOleg39 Jan 19, 2022

Contributor

One more question, can i wait a PR with fix, or better to do it myself?

This comment has been minimized.

Copy link
@dnalborczyk

dnalborczyk Jan 19, 2022

Author Contributor

One more question, can i wait a PR with fix, or better to do it myself?

I have something ready, need to add some tests.

This comment has been minimized.

Copy link
@dnalborczyk

dnalborczyk Jan 19, 2022

Author Contributor

No, that was intended as for an async hook, you have BOTH sync and async time measured. So the actual time is the sum of both times. In any case, I have long wondered if we should not get rid of the async time altogether as that one is not helpful at all because it does not measure time spent in the plugin but just the time between triggering and resolving. But as many modules are loaded in parallel, even a fast hook can get slow async timings because other async code may be executed in between. And the sum of those times can far exceed the total build time. If we want to improve something here, I would suggest to remove the second async timer altogether but for async hooks, extend the label e.g. (excluding async time) to signal there is more stuff that was not measured.

I'll have a look. I thought that the timings were off when building rollup itself with perf:true, specially the async timings didn't fit (the remaining might have, don't remember exactly).

the performance api which we now use in the browser and node.js is capable of measuring async code while keeping the context. I was in the midst to switch to that completely as well (replacing the Map with it), but wasn't able to add the memory usage for each perf measurement. I believe detail could be used, but unfortunately that was added in node.js v16: https://nodejs.org/docs/latest-v16.x/api/perf_hooks.html#performancemarkname-options (not sure about the browser)

This comment has been minimized.

Copy link
@lukastaegert

lukastaegert Jan 20, 2022

Author Member

As the perf option is considered experimental, I would be ok with a breaking change in a minor version. Maybe we just separate the memory measurements from the timings, and just give some vague information for now. If we can really get correct async information that ignores time spent in other interleaved async functions, that would be tremendous. I must admit I did not look too deeply into the capabilities of that API.

This comment has been minimized.

Copy link
@dnalborczyk

dnalborczyk Jan 21, 2022

Author Contributor

in that case, I'll give it a go 👍

timeEnd(timerLabel, 4);
if (result && typeof result.then === 'function') {
timeStart(`${timerLabel} (async)`, 4);
result = result.then((hookResult: unknown) => {
return result.then((hookResult: unknown) => {
timeEnd(`${timerLabel} (async)`, 4);
return hookResult;
});
}
return result;
};
} else {
timedPlugin[hook] = plugin[hook];
}
}
return timedPlugin as Plugin;
return {
...plugin,
...timedPlugin
};
}

export function initialiseTimers(inputOptions: InputOptions): void {
if (inputOptions.perf) {
timers = {};
setTimeHelpers();
timers = new Map();
timeStart = timeStartImpl;
timeEnd = timeEndImpl;
inputOptions.plugins = inputOptions.plugins!.map(getPluginWithTimers);
Expand Down
5 changes: 5 additions & 0 deletions test/browser/index.js
@@ -1,3 +1,8 @@
// since we don't run the browser tests in an actual browser, we need to make `performance`
// globally accessible same as in the browser. this can be removed once `performance` is
// available globally in all supported platforms. [currently global for node.js v16+].
global.performance = require('perf_hooks').performance;

const { basename, resolve } = require('path');
const fixturify = require('fixturify');
const { rollup } = require('../../dist/rollup.browser.js');
Expand Down

0 comments on commit 7c47283

Please sign in to comment.