From b289f0c5e2e5bef0efcec4a1c19041b7ec86064b Mon Sep 17 00:00:00 2001 From: Johannes Rieken Date: Mon, 6 Nov 2017 18:50:57 +0100 Subject: [PATCH] rename startupTimer to performance, support mark and measure, drop promise support, add more marks to slowly phase out old timers --- build/gulpfile.vscode.js | 2 +- src/main.js | 4 + src/vs/base/common/performance.d.ts | 17 +++ src/vs/base/common/performance.js | 106 +++++++++++++++ src/vs/base/node/startupTimers.d.ts | 39 ------ src/vs/base/node/startupTimers.js | 128 ------------------ src/vs/code/electron-main/window.ts | 5 +- src/vs/platform/windows/common/windows.ts | 4 +- src/vs/workbench/electron-browser/actions.ts | 9 +- .../electron-browser/bootstrap/index.js | 12 +- .../workbench/electron-browser/workbench.ts | 15 +- .../electron-browser/extensionService.ts | 6 +- 12 files changed, 157 insertions(+), 190 deletions(-) create mode 100644 src/vs/base/common/performance.d.ts create mode 100644 src/vs/base/common/performance.js delete mode 100644 src/vs/base/node/startupTimers.d.ts delete mode 100644 src/vs/base/node/startupTimers.js diff --git a/build/gulpfile.vscode.js b/build/gulpfile.vscode.js index 31f3e0efe5d..78531a2a0ca 100644 --- a/build/gulpfile.vscode.js +++ b/build/gulpfile.vscode.js @@ -68,7 +68,7 @@ const vscodeResources = [ 'out-build/bootstrap-amd.js', 'out-build/paths.js', 'out-build/vs/**/*.{svg,png,cur,html}', - 'out-build/vs/base/node/startupTimers.js', + 'out-build/vs/base/common/performance.js', 'out-build/vs/base/node/{stdForkStart.js,terminateProcess.sh}', 'out-build/vs/base/browser/ui/octiconLabel/octicons/**', 'out-build/vs/workbench/browser/media/*-theme.css', diff --git a/src/main.js b/src/main.js index 3c6611e36aa..7b31fc5dcab 100644 --- a/src/main.js +++ b/src/main.js @@ -12,6 +12,9 @@ if (process.argv.indexOf('--prof-startup') >= 0) { profiler.startProfiling('main', true); } +var perf = require('./vs/base/common/performance'); +perf.mark('main:started'); + // Perf measurements global.perfStartTime = Date.now(); @@ -218,6 +221,7 @@ var nodeCachedDataDir = getNodeCachedDataDir().then(function (value) { // Load our code once ready app.once('ready', function () { + perf.mark('main:appReady'); global.perfAppReady = Date.now(); var nlsConfig = getNLSConfiguration(); process.env['VSCODE_NLS_CONFIG'] = JSON.stringify(nlsConfig); diff --git a/src/vs/base/common/performance.d.ts b/src/vs/base/common/performance.d.ts new file mode 100644 index 00000000000..f65e9c07e93 --- /dev/null +++ b/src/vs/base/common/performance.d.ts @@ -0,0 +1,17 @@ +/*--------------------------------------------------------------------------------------------- + * Copyright (c) Microsoft Corporation. All rights reserved. + * Licensed under the MIT License. See License.txt in the project root for license information. + *--------------------------------------------------------------------------------------------*/ + +export interface PerformanceEntry { + readonly type: 'mark' | 'measure'; + readonly name: string; + readonly startTime: number; + readonly duration: number; +} + +export function mark(name: string): void; +export function measure(name: string, from?: string, to?: string): void; +export function time(name: string): { stop(): void }; +export function getEntries(type?: 'mark' | 'measure'): PerformanceEntry[]; +export function importEntries(entries: PerformanceEntry[]): void; diff --git a/src/vs/base/common/performance.js b/src/vs/base/common/performance.js new file mode 100644 index 00000000000..578f8a79dee --- /dev/null +++ b/src/vs/base/common/performance.js @@ -0,0 +1,106 @@ +/*--------------------------------------------------------------------------------------------- + * Copyright (c) Microsoft Corporation. All rights reserved. + * Licensed under the MIT License. See License.txt in the project root for license information. + *--------------------------------------------------------------------------------------------*/ + +'use strict'; + +/*global define*/ + +// This module can be loaded in an amd and commonjs-context. +// Because we want both instances to use the same perf-data +// we store them globally +global._performanceEntries = global._performanceEntries || []; + +if (typeof define !== "function" && typeof module === "object" && typeof module.exports === "object") { + // this is commonjs, fake amd + global.define = function (dep, callback) { + module.exports = callback(); + global.define = undefined; + }; +} + +define([], function () { + + // const _now = global.performance && performance.now ? performance.now : Date.now + const _now = Date.now; + + class PerformanceEntry { + constructor(type, name, startTime, duration) { + this.type = type; + this.name = name; + this.startTime = startTime; + this.duration = duration; + } + } + + function _getEntry(type, name) { + for (let i = global._performanceEntries.length - 1; i >= 0; i--) { + if ( + (type === undefined || global._performanceEntries[i].type === type) && + (name === undefined || global._performanceEntries[i].name === name) + ) { + return global._performanceEntries[i]; + } + } + } + + function importEntries(entries) { + global._performanceEntries.splice(0, 0, ...entries); + } + + function getEntries(type, name) { + return global._performanceEntries.filter(entry => { + return (type === undefined || entry.type === type) && + (name === undefined || entry.name === name); + }).sort((a, b) => { + return a.startTime - b.startTime; + }); + } + + function mark(name) { + const entry = new PerformanceEntry('mark', name, _now(), 0); + global._performanceEntries.push(entry); + if (typeof console.timeStamp === 'function') { + console.timeStamp(name); + } + } + + function time(name) { + let from = `${name}/start`; + mark(from); + return { stop() { measure(name, from); } }; + } + + function measure(name, from, to) { + + let startTime; + let duration; + let now = _now(); + + if (!from) { + startTime = now; + } else { + startTime = _getEntry(undefined, from).startTime; + } + + if (!to) { + duration = now - startTime; + } else { + duration = _getEntry(undefined, to).startTime - startTime; + } + + const entry = new PerformanceEntry('measure', name, startTime, duration); + global._performanceEntries.push(entry); + } + + var exports = { + mark: mark, + measure: measure, + time: time, + getEntries: getEntries, + importEntries: importEntries + }; + + return exports; +}); diff --git a/src/vs/base/node/startupTimers.d.ts b/src/vs/base/node/startupTimers.d.ts deleted file mode 100644 index 432cb72088e..00000000000 --- a/src/vs/base/node/startupTimers.d.ts +++ /dev/null @@ -1,39 +0,0 @@ -/*--------------------------------------------------------------------------------------------- - * Copyright (c) Microsoft Corporation. All rights reserved. - * Licensed under the MIT License. See License.txt in the project root for license information. - *--------------------------------------------------------------------------------------------*/ - -import { Profile } from './profiler'; - -declare interface TickStart { - name: string; - started: number; -} - -export declare class Tick { - - readonly duration: number; - readonly name: string; - readonly started: number; - readonly stopped: number; - readonly profile: Profile; - - static compareByStart(a: Tick, b: Tick): number; -} - -declare interface TickController { - while>(t: T): T; - stop(stopped?: number): void; -} - -export function startTimer(name: string): TickController; - -export function stopTimer(name: string): void; - -export function ticks(): Tick[]; - -export function tick(name: string): Tick; - -export function setProfileList(names: string[]): void; - -export function disable(): void; diff --git a/src/vs/base/node/startupTimers.js b/src/vs/base/node/startupTimers.js deleted file mode 100644 index 19dfaba74fc..00000000000 --- a/src/vs/base/node/startupTimers.js +++ /dev/null @@ -1,128 +0,0 @@ -/*--------------------------------------------------------------------------------------------- - * Copyright (c) Microsoft Corporation. All rights reserved. - * Licensed under the MIT License. See License.txt in the project root for license information. - *--------------------------------------------------------------------------------------------*/ - -'use strict'; - -/*global define*/ - -var requireProfiler; - -if (typeof define !== "function" && typeof module === "object" && typeof module.exports === "object") { - // this is commonjs, fake amd - global.define = function (dep, callback) { - module.exports = callback(); - global.define = undefined; - }; - requireProfiler = function () { - return require('v8-profiler'); - }; -} else { - // this is amd - requireProfiler = function () { - return require.__$__nodeRequire('v8-profiler'); - }; -} - -define([], function () { - - function Tick(name, started, stopped, profile) { - this.name = name; - this.started = Math.round((started[0] * 1e9 + started[1]) / 1e6); - this.stopped = Math.round((stopped[0] * 1e9 + stopped[1]) / 1e6); - this.duration = Math.round(((stopped[0] * 1.e9 + stopped[1]) - (started[0] * 1e9 + started[1])) / 1.e6); - this.profile = profile; - } - Tick.compareByStart = function (a, b) { - if (a.started < b.started) { - return -1; - } else if (a.started > b.started) { - return 1; - } else { - return 0; - } - }; - - // This module can be loaded in an amd and commonjs-context. - // Because we want both instances to use the same tick-data - // we store them globally - global._perfStarts = global._perfStarts || new Map(); - global._perfTicks = global._perfTicks || new Map(); - global._perfToBeProfiled = global._perfToBeProfiled || new Set(); - - var _starts = global._perfStarts; - var _ticks = global._perfTicks; - var _toBeProfiled = global._perfToBeProfiled; - - function startTimer(name) { - if (_starts.has(name)) { - throw new Error("${name}" + " already exists"); - } - if (_toBeProfiled.has(name)) { - requireProfiler().startProfiling(name, true); - } - _starts.set(name, { name: name, started: process.hrtime() }); - var stop = stopTimer.bind(undefined, name); - return { - stop: stop, - while: function (thenable) { - thenable.then(function () { stop(); }, function () { stop(); }); - return thenable; - } - }; - } - - function stopTimer(name) { - var profile = _toBeProfiled.has(name) ? requireProfiler().stopProfiling(name) : undefined; - var start = _starts.get(name); - if (start !== undefined) { - var tick = new Tick(start.name, start.started, process.hrtime(), profile); - _ticks.set(name, tick); - _starts.delete(name); - } - } - - function ticks() { - var ret = []; - _ticks.forEach(function (value) { ret.push(value); }); - return ret.sort((a, b) => a.started - b.started); - } - - function tick(name) { - var ret = _ticks.get(name); - if (!ret) { - var now = Date.now(); - ret = new Tick(name, now, now); - } - return ret; - } - - function setProfileList(names) { - _toBeProfiled.clear(); - names.forEach(function (name) { _toBeProfiled.add(name); }); - } - - var exports = { - Tick: Tick, - startTimer: startTimer, - stopTimer: stopTimer, - ticks: ticks, - tick: tick, - setProfileList: setProfileList, - disable: disable, - }; - - function disable() { - var emptyController = Object.freeze({ while: function (t) { return t; }, stop: function () { } }); - var emptyTicks = Object.create([]); - exports.startTimer = function () { return emptyController; }; - exports.stopTimer = function () { }; - exports.ticks = function () { return emptyTicks; }; - - delete global._perfStarts; - delete global._perfTicks; - } - - return exports; -}); diff --git a/src/vs/code/electron-main/window.ts b/src/vs/code/electron-main/window.ts index e27bbf1b4ca..d06769cc905 100644 --- a/src/vs/code/electron-main/window.ts +++ b/src/vs/code/electron-main/window.ts @@ -26,6 +26,7 @@ import { ICodeWindow } from 'vs/platform/windows/electron-main/windows'; import { IWorkspaceIdentifier, IWorkspacesMainService } from 'vs/platform/workspaces/common/workspaces'; import { IBackupMainService } from 'vs/platform/backup/common/backup'; import { ICommandAction } from 'vs/platform/actions/common/actions'; +import { mark, getEntries } from 'vs/base/common/performance'; export interface IWindowState { width?: number; @@ -507,6 +508,7 @@ export class CodeWindow implements ICodeWindow { } // Load URL + mark('main:loadWindow'); this._win.loadURL(this.getUrl(config)); // Make window visible if it did not open in N seconds because this indicates an error @@ -578,6 +580,7 @@ export class CodeWindow implements ICodeWindow { windowConfiguration.backgroundColor = this.getBackgroundColor(); // Perf Counters + windowConfiguration.perfEntries = getEntries(); windowConfiguration.perfStartTime = global.perfStartTime; windowConfiguration.perfAppReady = global.perfAppReady; windowConfiguration.perfWindowLoadTime = Date.now(); @@ -971,4 +974,4 @@ export class CodeWindow implements ICodeWindow { this._win = null; // Important to dereference the window object to allow for GC } -} \ No newline at end of file +} diff --git a/src/vs/platform/windows/common/windows.ts b/src/vs/platform/windows/common/windows.ts index f89f33246a2..80a76149dee 100644 --- a/src/vs/platform/windows/common/windows.ts +++ b/src/vs/platform/windows/common/windows.ts @@ -14,6 +14,7 @@ import { ParsedArgs } from 'vs/platform/environment/common/environment'; import { IWorkspaceIdentifier, IWorkspaceFolderCreationData } from 'vs/platform/workspaces/common/workspaces'; import { IRecentlyOpened } from 'vs/platform/history/common/history'; import { ICommandAction } from 'vs/platform/actions/common/actions'; +import { PerformanceEntry } from 'vs/base/common/performance'; export const IWindowsService = createDecorator('windowsService'); @@ -255,6 +256,7 @@ export interface IWindowConfiguration extends ParsedArgs, IOpenFileRequest { backgroundColor?: string; accessibilitySupport?: boolean; + perfEntries: PerformanceEntry[]; perfStartTime?: number; perfAppReady?: number; perfWindowLoadTime?: number; @@ -263,4 +265,4 @@ export interface IWindowConfiguration extends ParsedArgs, IOpenFileRequest { export interface IRunActionInWindowRequest { id: string; from: 'menu' | 'touchbar' | 'mouse'; -} \ No newline at end of file +} diff --git a/src/vs/workbench/electron-browser/actions.ts b/src/vs/workbench/electron-browser/actions.ts index 92ab25984b3..780ce0463c2 100644 --- a/src/vs/workbench/electron-browser/actions.ts +++ b/src/vs/workbench/electron-browser/actions.ts @@ -45,7 +45,7 @@ import { IWorkspaceIdentifier, getWorkspaceLabel, ISingleFolderWorkspaceIdentifi import { FileKind } from 'vs/platform/files/common/files'; import { IInstantiationService } from 'vs/platform/instantiation/common/instantiation'; import { IExtensionService } from 'vs/platform/extensions/common/extensions'; -import { ticks } from 'vs/base/node/startupTimers'; +import { getEntries } from 'vs/base/common/performance'; // --- actions @@ -367,9 +367,10 @@ export class ShowStartupPerformance extends Action { (console).group('Raw Startup Timers (CSV)'); let value = `Name\tStart\tDuration\n`; - let offset = ticks()[0].started; - for (const tick of ticks()) { - value += `${tick.name}\t${tick.started - offset}\t${tick.duration}\n`; + const entries = getEntries('measure'); + let offset = entries[0].startTime; + for (const entry of entries) { + value += `${entry.name}\t${entry.startTime - offset}\t${entry.duration}\n`; } console.log(value); (console).groupEnd(); diff --git a/src/vs/workbench/electron-browser/bootstrap/index.js b/src/vs/workbench/electron-browser/bootstrap/index.js index 8961feef2a7..f5ede45b1fd 100644 --- a/src/vs/workbench/electron-browser/bootstrap/index.js +++ b/src/vs/workbench/electron-browser/bootstrap/index.js @@ -14,7 +14,9 @@ if (window.location.search.indexOf('prof-startup') >= 0) { /*global window,document,define,Monaco_Loader_Init*/ -const startTimer = require('../../../base/node/startupTimers').startTimer; +const perf = require('../../../base/common/performance'); +perf.mark('renderer/started'); + const path = require('path'); const electron = require('electron'); const remote = electron.remote; @@ -124,6 +126,7 @@ function main() { // Correctly inherit the parent's environment assign(process.env, configuration.userEnv); + perf.importEntries(configuration.perfEntries); // Get the nls configuration into the process.env as early as possible. var nlsConfig = { availableLanguages: {} }; @@ -161,7 +164,6 @@ function main() { window.nodeRequire = require.__$__nodeRequire; define('fs', ['original-fs'], function (originalFS) { return originalFS; }); // replace the patched electron fs with the original node fs for all AMD code - loaderTimer.stop(); window.MonacoEnvironment = {}; @@ -191,13 +193,13 @@ function main() { beforeLoadWorkbenchMain: Date.now() }; - const workbenchMainTimer = startTimer('load:workbench.main'); + const workbenchMainClock = perf.time('loadWorkbenchMain'); require([ 'vs/workbench/workbench.main', 'vs/nls!vs/workbench/workbench.main', 'vs/css!vs/workbench/workbench.main' ], function () { - workbenchMainTimer.stop(); + workbenchMainClock.stop(); timers.afterLoadWorkbenchMain = Date.now(); process.lazyEnv.then(function () { @@ -213,8 +215,6 @@ function main() { } // In the bundled version the nls plugin is packaged with the loader so the NLS Plugins - // loads as soon as the loader loads. To be able to have pseudo translation - const loaderTimer = startTimer('load:loader'); if (typeof Monaco_Loader_Init === 'function') { const loader = Monaco_Loader_Init(); //eslint-disable-next-line no-global-assign diff --git a/src/vs/workbench/electron-browser/workbench.ts b/src/vs/workbench/electron-browser/workbench.ts index 08ef14e2c2d..75d3cc04331 100644 --- a/src/vs/workbench/electron-browser/workbench.ts +++ b/src/vs/workbench/electron-browser/workbench.ts @@ -16,7 +16,7 @@ import { Builder, $ } from 'vs/base/browser/builder'; import { Delayer, RunOnceScheduler } from 'vs/base/common/async'; import * as browser from 'vs/base/browser/browser'; import { StopWatch } from 'vs/base/common/stopwatch'; -import { startTimer } from 'vs/base/node/startupTimers'; +import { time } from 'vs/base/common/performance'; import errors = require('vs/base/common/errors'); import { BackupFileService } from 'vs/workbench/services/backup/node/backupFileService'; import { IBackupFileService } from 'vs/workbench/services/backup/common/backup'; @@ -320,9 +320,10 @@ export class Workbench implements IPartService { } viewletRestoreStopWatch = StopWatch.create(); - const viewletTimer = startTimer('restore:viewlet'); - compositeAndEditorPromises.push(viewletTimer.while(this.viewletService.openViewlet(viewletIdToRestore)).then(() => { + const viewletRestoreClock = time('restore:viewlet'); + compositeAndEditorPromises.push(this.viewletService.openViewlet(viewletIdToRestore).then(() => { viewletRestoreStopWatch.stop(); + viewletRestoreClock.stop(); })); } @@ -335,9 +336,9 @@ export class Workbench implements IPartService { // Load Editors const editorRestoreStopWatch = StopWatch.create(); + const editorRestoreClock = time('restore:editors'); const restoredEditors: string[] = []; - const editorsTimer = startTimer('restore:editors'); - compositeAndEditorPromises.push(editorsTimer.while(this.resolveEditorsToOpen().then(inputs => { + compositeAndEditorPromises.push(this.resolveEditorsToOpen().then(inputs => { let editorOpenPromise: TPromise; if (inputs.length) { editorOpenPromise = this.editorService.openEditors(inputs.map(input => { return { input, position: EditorPosition.ONE }; })); @@ -347,8 +348,8 @@ export class Workbench implements IPartService { return editorOpenPromise.then(editors => { this.handleEditorBackground(); // make sure we show the proper background in the editor area + editorRestoreClock.stop(); editorRestoreStopWatch.stop(); - for (const editor of editors) { if (editor) { if (editor.input) { @@ -359,7 +360,7 @@ export class Workbench implements IPartService { } } }); - }))); + })); if (this.storageService.getBoolean(Workbench.zenModeActiveSettingKey, StorageScope.WORKSPACE, false)) { this.toggleZenMode(true); diff --git a/src/vs/workbench/services/extensions/electron-browser/extensionService.ts b/src/vs/workbench/services/extensions/electron-browser/extensionService.ts index 7f6a33edc85..afbd40e9494 100644 --- a/src/vs/workbench/services/extensions/electron-browser/extensionService.ts +++ b/src/vs/workbench/services/extensions/electron-browser/extensionService.ts @@ -32,7 +32,7 @@ import { ExtHostCustomersRegistry } from 'vs/workbench/api/electron-browser/extH import { IWindowService } from 'vs/platform/windows/common/windows'; import { Action } from 'vs/base/common/actions'; import { IDisposable } from 'vs/base/common/lifecycle'; -import { startTimer } from 'vs/base/node/startupTimers'; +import { mark, time } from 'vs/base/common/performance'; import { toPromise, filterEvent } from 'vs/base/common/event'; import { ILifecycleService, LifecyclePhase } from 'vs/platform/lifecycle/common/lifecycle'; @@ -336,14 +336,14 @@ export class ExtensionService implements IExtensionService { let messageHandler = (msg: IMessage) => this._handleExtensionPointMessage(msg); for (let i = 0, len = extensionPoints.length; i < len; i++) { - const clock = startTimer(`handleExtensionPoint:${extensionPoints[i].name}`); + const clock = time(`handleExtensionPoint:${extensionPoints[i].name}`); try { ExtensionService._handleExtensionPoint(extensionPoints[i], availableExtensions, messageHandler); } finally { clock.stop(); } } - + mark('extensionHostReady'); this._barrier.open(); }); }