From 8ac9275068ef2f687938ec220a09d3d3dd029bae Mon Sep 17 00:00:00 2001 From: Benjamin Pasero Date: Mon, 21 Nov 2016 09:45:07 +0100 Subject: [PATCH] perf - tweak the output in console --- src/vs/workbench/electron-browser/actions.ts | 103 +++++++------------ src/vs/workbench/electron-browser/common.ts | 6 +- src/vs/workbench/electron-browser/shell.ts | 8 +- 3 files changed, 45 insertions(+), 72 deletions(-) diff --git a/src/vs/workbench/electron-browser/actions.ts b/src/vs/workbench/electron-browser/actions.ts index b989aaa6f74..bf1d9eb870c 100644 --- a/src/vs/workbench/electron-browser/actions.ts +++ b/src/vs/workbench/electron-browser/actions.ts @@ -7,7 +7,6 @@ import URI from 'vs/base/common/uri'; import { TPromise } from 'vs/base/common/winjs.base'; -import timer = require('vs/base/common/timer'); import { Action } from 'vs/base/common/actions'; import { IWindowIPCService } from 'vs/workbench/services/window/electron-browser/windowService'; import { IWindowService, IWindowsService } from 'vs/platform/windows/common/windows'; @@ -331,7 +330,6 @@ export class ShowStartupPerformance extends Action { } public run(): TPromise { - const perfTable = this.environmentService.performance ? this.getPerformanceTable() : this.getFingerprintTable(); // Show dev tools this.windowService.openDevTools(); @@ -346,81 +344,55 @@ export class ShowStartupPerformance extends Action { console.log(`Initial Startup: ${fingerprint.initialStartup}`); console.log(`Screen Reader Active: ${fingerprint.hasAccessibilitySupport}`); console.log(`Empty Workspace: ${fingerprint.emptyWorkbench}`); - (console).table(perfTable); + + let nodeModuleLoadTime: number; + let nodeModuleLoadDetails: any[]; + if (this.environmentService.performance) { + const nodeModuleTimes = this.analyzeNodeModulesLoadTimes(); + nodeModuleLoadTime = nodeModuleTimes.duration; + nodeModuleLoadDetails = nodeModuleTimes.table; + } + + (console).table(this.getFingerprintTable(nodeModuleLoadTime)); + + if (nodeModuleLoadDetails) { + (console).groupCollapsed('node_modules Load Details'); + (console).table(nodeModuleLoadDetails); + (console).groupEnd(); + } (console).groupEnd(); }, 1000); return TPromise.as(true); } - private getFingerprintTable(): any[] { + private getFingerprintTable(nodeModuleLoadTime?: number): any[] { const table: any[] = []; const fingerprint: IStartupFingerprint = timers.fingerprint; if (fingerprint.initialStartup) { - table.push({ Topic: '[main] initial start => begin to require(workbench.main.js)', 'Took (ms)': fingerprint.timers.ellapsedMain }); + table.push({ Topic: '[main] start => window.loadUrl()', 'Took (ms)': fingerprint.timers.ellapsedWindowLoad }); } + + table.push({ Topic: '[renderer] window.loadUrl() => begin to require(workbench.main.js)', 'Took (ms)': fingerprint.timers.ellapsedWindowLoadToRequire }); table.push({ Topic: '[renderer] require(workbench.main.js)', 'Took (ms)': fingerprint.timers.ellapsedRequire }); + + if (nodeModuleLoadTime) { + table.push({ Topic: '[renderer] -> of which require() node_modules', 'Took (ms)': nodeModuleLoadTime }); + } + table.push({ Topic: '[renderer] create extension host => extensions onReady()', 'Took (ms)': fingerprint.timers.ellapsedExtensions }); table.push({ Topic: '[renderer] restore viewlet', 'Took (ms)': fingerprint.timers.ellapsedViewletRestore }); - table.push({ Topic: '[renderer] restoring editor view state', 'Took (ms)': fingerprint.timers.ellapsedEditorRestore }); + table.push({ Topic: '[renderer] restore editor view state', 'Took (ms)': fingerprint.timers.ellapsedEditorRestore }); table.push({ Topic: '[renderer] overall workbench load', 'Took (ms)': fingerprint.timers.ellapsedWorkbench }); table.push({ Topic: '------------------------------------------------------' }); - if (fingerprint.initialStartup) { - table.push({ Topic: '[main] load window at', 'Start (ms)': fingerprint.timers.windowLoad }); - } - table.push({ Topic: '[main, renderer] start => extensions ready', 'Took (ms)': fingerprint.timers.extensionsReady }); + table.push({ Topic: '[main, renderer] start => extensions ready', 'Took (ms)': fingerprint.timers.ellapsedExtensionsReady }); table.push({ Topic: '[main, renderer] start => workbench ready', 'Took (ms)': fingerprint.ellapsed }); return table; } - private getPerformanceTable(): any[] { - const table: any[] = []; - table.push(...this.analyzeLoaderTimes()); - - const start = Math.round(timers.isInitialStartup ? timers.perfStartTime : timers.perfWindowLoadTime); - - let lastEvent: timer.ITimerEvent; - const events = timer.getTimeKeeper().getCollectedEvents(); - events.forEach((e) => { - if (e.topic === 'Startup') { - lastEvent = e; - const entry: any = {}; - - entry['Event'] = e.name; - entry['Took (ms)'] = e.stopTime.getTime() - e.startTime.getTime(); - entry['Start (ms)'] = Math.max(e.startTime.getTime() - start, 0); - entry['End (ms)'] = e.stopTime.getTime() - start; - - table.push(entry); - } - }); - - table.push({ Event: '------------------------------------------------------' }); - - if (timers.isInitialStartup) { - const loadWindow = Math.round(timers.perfWindowLoadTime); - const windowLoadEvent: any = {}; - windowLoadEvent['Event'] = '[main] load window at'; - windowLoadEvent['Start (ms)'] = loadWindow - start; - table.push(windowLoadEvent); - } - - const totalExtensions: any = {}; - totalExtensions['Event'] = '[main, renderer] start => extensions ready'; - totalExtensions['Took (ms)'] = timers.perfAfterExtensionLoad - start; - table.push(totalExtensions); - - const totalWorkbench: any = {}; - totalWorkbench['Event'] = '[main, renderer] start => workbench ready'; - totalWorkbench['Took (ms)'] = timers.workbenchStarted - start; - table.push(totalWorkbench); - - return table; - } - - private analyzeLoaderTimes(): any[] { + private analyzeNodeModulesLoadTimes(): { table: any[], duration: number } { const stats = (require).getStats(); const result = []; @@ -430,28 +402,29 @@ export class ShowStartupPerformance extends Action { if (stats[i].type === LoaderEventType.NodeEndNativeRequire) { if (stats[i - 1].type === LoaderEventType.NodeBeginNativeRequire && stats[i - 1].detail === stats[i].detail) { const entry: any = {}; + const dur = (stats[i].timestamp - stats[i - 1].timestamp); entry['Event'] = 'nodeRequire ' + stats[i].detail; - entry['Took (ms)'] = (stats[i].timestamp - stats[i - 1].timestamp); - total += (stats[i].timestamp - stats[i - 1].timestamp); - entry['Start (ms)'] = '**' + stats[i - 1].timestamp; - entry['End (ms)'] = '**' + stats[i - 1].timestamp; + entry['Took (ms)'] = dur.toFixed(2); + total += dur; + entry['Start (ms)'] = '**' + stats[i - 1].timestamp.toFixed(2); + entry['End (ms)'] = '**' + stats[i - 1].timestamp.toFixed(2); result.push(entry); } } } if (total > 0) { + result.push({ Event: '------------------------------------------------------' }); + const entry: any = {}; - entry['Event'] = '[renderer] total require() node modules'; - entry['Took (ms)'] = total; + entry['Event'] = '[renderer] total require() node_modules'; + entry['Took (ms)'] = total.toFixed(2); entry['Start (ms)'] = '**'; entry['End (ms)'] = '**'; result.push(entry); - - result.push({ Event: '------------------------------------------------------' }); } - return result; + return { table: result, duration: Math.round(total) }; } } diff --git a/src/vs/workbench/electron-browser/common.ts b/src/vs/workbench/electron-browser/common.ts index f64ed0f77a4..9f35d997209 100644 --- a/src/vs/workbench/electron-browser/common.ts +++ b/src/vs/workbench/electron-browser/common.ts @@ -25,10 +25,10 @@ export interface IWindowConfiguration { export interface IStartupFingerprint { ellapsed: number; timers: { - ellapsedMain?: number; - windowLoad?: number; + ellapsedWindowLoad?: number; + ellapsedWindowLoadToRequire: number; ellapsedExtensions: number; - extensionsReady: number; + ellapsedExtensionsReady: number; ellapsedRequire: number; ellapsedViewletRestore: number; ellapsedEditorRestore: number; diff --git a/src/vs/workbench/electron-browser/shell.ts b/src/vs/workbench/electron-browser/shell.ts index 26f0f23e666..ced0f08c2ef 100644 --- a/src/vs/workbench/electron-browser/shell.ts +++ b/src/vs/workbench/electron-browser/shell.ts @@ -239,11 +239,12 @@ export class WorkbenchShell { ellapsed: Math.round(workbenchStarted - start), timers: { ellapsedExtensions: Math.round(timers.perfAfterExtensionLoad - timers.perfBeforeExtensionLoad), - extensionsReady: Math.round(timers.perfAfterExtensionLoad - start), + ellapsedExtensionsReady: Math.round(timers.perfAfterExtensionLoad - start), ellapsedRequire: Math.round(timers.perfAfterLoadWorkbenchMain - timers.perfBeforeLoadWorkbenchMain), ellapsedViewletRestore: Math.round(restoreViewletDuration), ellapsedEditorRestore: Math.round(restoreEditorsDuration), - ellapsedWorkbench: Math.round(workbenchStarted - timers.perfBeforeWorkbenchOpen) + ellapsedWorkbench: Math.round(workbenchStarted - timers.perfBeforeWorkbenchOpen), + ellapsedWindowLoadToRequire: Math.round(timers.perfBeforeLoadWorkbenchMain - timers.perfWindowLoadTime) }, platform, release, @@ -256,8 +257,7 @@ export class WorkbenchShell { }; if (initialStartup) { - startupTimeEvent.timers.ellapsedMain = Math.round(timers.perfBeforeLoadWorkbenchMain - timers.perfStartTime); - startupTimeEvent.timers.windowLoad = Math.round(timers.perfWindowLoadTime - timers.perfStartTime); + startupTimeEvent.timers.ellapsedWindowLoad = Math.round(timers.perfWindowLoadTime - timers.perfStartTime); } this.telemetryService.publicLog('startupTime', startupTimeEvent); -- GitLab