diff --git a/src/vs/base/node/storage.ts b/src/vs/base/node/storage.ts index 0ed6195434a..998402042ed 100644 --- a/src/vs/base/node/storage.ts +++ b/src/vs/base/node/storage.ts @@ -10,6 +10,7 @@ import { RunOnceScheduler } from 'vs/base/common/async'; import { isUndefinedOrNull } from 'vs/base/common/types'; import { mapToString, setToString } from 'vs/base/common/map'; import { basename } from 'path'; +import { mark } from 'vs/base/common/performance'; export interface IStorageOptions { path: string; @@ -228,6 +229,9 @@ export interface IUpdateRequest { } export class SQLiteStorageImpl { + + private static measuredRequireDuration: boolean; // TODO@Ben remove me after a while + private db: Promise; private name: string; private logger: SQLiteStorageLogger; @@ -337,7 +341,18 @@ export class SQLiteStorageImpl { private doOpen(path: string): Promise { return new Promise((resolve, reject) => { + let measureRequireDuration = false; + if (!SQLiteStorageImpl.measuredRequireDuration) { + SQLiteStorageImpl.measuredRequireDuration = true; + measureRequireDuration = true; + + mark('willRequireSQLite'); + } import('vscode-sqlite3').then(sqlite3 => { + if (measureRequireDuration) { + mark('didRequireSQLite'); + } + const db = new (this.logger.verbose ? sqlite3.verbose().Database : sqlite3.Database)(path, error => { if (error) { return reject(error); diff --git a/src/vs/code/electron-browser/workbench/workbench.js b/src/vs/code/electron-browser/workbench/workbench.js index 6469759571d..d5017d77804 100644 --- a/src/vs/code/electron-browser/workbench/workbench.js +++ b/src/vs/code/electron-browser/workbench/workbench.js @@ -53,15 +53,11 @@ bootstrapWindow.load([ function showPartsSplash(configuration) { perf.mark('willShowPartsSplash'); - // TODO@Ben remove me after a while - perf.mark('willAccessLocalStorage'); - let storage = window.localStorage; - perf.mark('didAccessLocalStorage'); - let data; try { + // TODO@Ben remove me after a while perf.mark('willReadLocalStorage'); - let raw = storage.getItem('storage://global/parts-splash-data'); + let raw = window.localStorage.getItem('storage://global/parts-splash-data'); perf.mark('didReadLocalStorage'); data = JSON.parse(raw); } catch (e) { diff --git a/src/vs/platform/storage/node/storageService.ts b/src/vs/platform/storage/node/storageService.ts index e8224e48b9b..d145905e3e2 100644 --- a/src/vs/platform/storage/node/storageService.ts +++ b/src/vs/platform/storage/node/storageService.ts @@ -29,6 +29,10 @@ export class StorageService extends Disposable implements IStorageService { private _onWillSaveState: Emitter = this._register(new Emitter()); get onWillSaveState(): Event { return this._onWillSaveState.event; } + + private _hasErrors = false; + get hasErrors(): boolean { return this._hasErrors; } + private bufferedStorageErrors: (string | Error)[] = []; private _onStorageError: Emitter = this._register(new Emitter()); get onStorageError(): Event { @@ -69,6 +73,8 @@ export class StorageService extends Disposable implements IStorageService { errorLogger: error => { logService.error(error); + this._hasErrors = true; + if (Array.isArray(this.bufferedStorageErrors)) { this.bufferedStorageErrors.push(error); } else { @@ -101,13 +107,15 @@ export class StorageService extends Disposable implements IStorageService { } init(): Promise { - mark('willInitGlobalStorage'); mark('willInitWorkspaceStorage'); + return this.workspaceStorage.init().then(() => { + mark('didInitWorkspaceStorage'); - return Promise.all([ - this.globalStorage.init().then(() => mark('didInitGlobalStorage')), - this.workspaceStorage.init().then(() => mark('didInitWorkspaceStorage')) - ]).then(() => void 0); + mark('willInitGlobalStorage'); + return this.globalStorage.init().then(() => { + mark('didInitGlobalStorage'); + }); + }); } get(key: string, scope: StorageScope, fallbackValue: string): string; diff --git a/src/vs/workbench/electron-browser/main.ts b/src/vs/workbench/electron-browser/main.ts index be41a2eee09..2dc29a29797 100644 --- a/src/vs/workbench/electron-browser/main.ts +++ b/src/vs/workbench/electron-browser/main.ts @@ -292,7 +292,10 @@ function createStorageService(workspaceStorageFolder: string, payload: IWorkspac // Otherwise do a migration of previous workspace data if the DB does not exist yet // TODO@Ben remove me after one milestone const workspaceStorageDBPath = join(workspaceStorageFolder, 'storage.db'); + perf.mark('willCheckWorkspaceStorageExists'); return exists(workspaceStorageDBPath).then(exists => { + perf.mark('didCheckWorkspaceStorageExists'); + const storageService = new StorageService(workspaceStorageDBPath, logService, environmentService); return storageService.init().then(() => { @@ -300,6 +303,7 @@ function createStorageService(workspaceStorageFolder: string, payload: IWorkspac return storageService; // return early if DB was already there } + perf.mark('willMigrateWorkspaceStorageKeys'); return readdir(environmentService.extensionsPath).then(extensions => { // Otherwise, we migrate data from window.localStorage over @@ -417,6 +421,8 @@ function createStorageService(workspaceStorageFolder: string, payload: IWorkspac logService.error(error); } + perf.mark('didMigrateWorkspaceStorageKeys'); + return storageService; }); }); diff --git a/src/vs/workbench/electron-browser/shell.ts b/src/vs/workbench/electron-browser/shell.ts index ce89923580a..c155e592ba5 100644 --- a/src/vs/workbench/electron-browser/shell.ts +++ b/src/vs/workbench/electron-browser/shell.ts @@ -286,12 +286,14 @@ export class WorkbenchShell extends Disposable { private logStorageTelemetry(): void { const globalStorageInitDuration = perf.getDuration('willInitGlobalStorage', 'didInitGlobalStorage'); + const workspaceStorageRequireDuration = perf.getDuration('willRequireSQLite', 'didRequireSQLite'); const workspaceStorageInitDuration = perf.getDuration('willInitWorkspaceStorage', 'didInitWorkspaceStorage'); + const workspaceStorageFileExistsDuration = perf.getDuration('willCheckWorkspaceStorageExists', 'didCheckWorkspaceStorageExists'); + const workspaceStorageMigrationDuration = perf.getDuration('willMigrateWorkspaceStorageKeys', 'didMigrateWorkspaceStorageKeys'); const workbenchLoadDuration = perf.getDuration('willLoadWorkbenchMain', 'didLoadWorkbenchMain'); - const localStorageAccessDuration = perf.getDuration('willAccessLocalStorage', 'didAccessLocalStorage'); - const localStorageReadDuration = perf.getDuration('willReadLocalStorage', 'didReadLocalStorage'); + const localStorageDuration = perf.getDuration('willReadLocalStorage', 'didReadLocalStorage'); - let workspaceIntegrity: string; + let workspaceIntegrity = 'unresolved'; // Handle errors (avoid duplicates to reduce spam) const loggedStorageErrors = new Set(); @@ -302,29 +304,33 @@ export class WorkbenchShell extends Disposable { loggedStorageErrors.add(errorStr); /* __GDPR__ - "sqliteStorageError2" : { + "sqliteStorageError3" : { "globalReadTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, + "workspaceExistsTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, + "workspaceRequireTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, "workspaceReadTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, - "localStorageAccessTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, - "localStorageReadTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, + "workspaceMigrationTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, + "localStorageTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, "workbenchRequireTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, "globalKeys" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, "workspaceKeys" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, "startupKind": { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, - "workspaceIntegrity" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, + "integrityWorkspace" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, "storageError": { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true } } */ - this.telemetryService.publicLog('sqliteStorageError2', { + this.telemetryService.publicLog('sqliteStorageError3', { 'globalReadTime': globalStorageInitDuration, + 'workspaceExistsTime': workspaceStorageFileExistsDuration, + 'workspaceMigrationTime': workspaceStorageMigrationDuration, + 'workspaceRequireTime': workspaceStorageRequireDuration, 'workspaceReadTime': workspaceStorageInitDuration, - 'localStorageAccessTime': localStorageAccessDuration, - 'localStorageReadTime': localStorageReadDuration, + 'localStorageTime': localStorageDuration, 'workbenchRequireTime': workbenchLoadDuration, 'globalKeys': this.storageService.storage.getSize(StorageScope.GLOBAL), 'workspaceKeys': this.storageService.storage.getSize(StorageScope.WORKSPACE), 'startupKind': this.lifecycleService.startupKind, - 'workspaceIntegrity': workspaceIntegrity, + 'integrityWorkspace': workspaceIntegrity, 'storageError': errorStr }); } @@ -334,15 +340,27 @@ export class WorkbenchShell extends Disposable { this.storageService.storage.checkIntegrity(StorageScope.WORKSPACE, false).then(integrity => { perf.mark('didCheckWorkspaceStorageIntegrity'); - workspaceIntegrity = integrity; + if (integrity) { + workspaceIntegrity = integrity; + } + + if (this.storageService.storage.hasErrors) { + return; // do not log performance numbers when errors occured + } + + if (this.environmentService.verbose || this.environmentService.logStorage) { + return; // do not log when running in verbose mode + } /* __GDPR__ - "sqliteStorageTimers2" : { + "sqliteStorageTimers3" : { "globalReadTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, + "workspaceExistsTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, + "workspaceMigrationTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, + "workspaceRequireTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, "workspaceReadTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, - "localStorageAccessTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, - "localStorageReadTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, - "workspaceIntegrity" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, + "localStorageTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, + "integrityWorkspace" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, "workspaceIntegrityCheckTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, "workbenchRequireTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, "globalKeys" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }, @@ -350,12 +368,14 @@ export class WorkbenchShell extends Disposable { "startupKind": { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true } } */ - this.telemetryService.publicLog('sqliteStorageTimers2', { + this.telemetryService.publicLog('sqliteStorageTimers3', { 'globalReadTime': globalStorageInitDuration, + 'workspaceExistsTime': workspaceStorageFileExistsDuration, + 'workspaceMigrationTime': workspaceStorageMigrationDuration, + 'workspaceRequireTime': workspaceStorageRequireDuration, 'workspaceReadTime': workspaceStorageInitDuration, - 'localStorageAccessTime': localStorageAccessDuration, - 'localStorageReadTime': localStorageReadDuration, - 'workspaceIntegrity': workspaceIntegrity, + 'localStorageTime': localStorageDuration, + 'integrityWorkspace': workspaceIntegrity, 'workspaceIntegrityCheckTime': perf.getDuration('willCheckWorkspaceStorageIntegrity', 'didCheckWorkspaceStorageIntegrity'), 'workbenchRequireTime': workbenchLoadDuration, 'globalKeys': this.storageService.storage.getSize(StorageScope.GLOBAL), diff --git a/src/vs/workbench/parts/performance/electron-browser/actions.ts b/src/vs/workbench/parts/performance/electron-browser/actions.ts index d54517c7fc0..1c182299554 100644 --- a/src/vs/workbench/parts/performance/electron-browser/actions.ts +++ b/src/vs/workbench/parts/performance/electron-browser/actions.ts @@ -33,7 +33,8 @@ class Info { table['window.loadUrl() => begin to require(workbench.main.js)'] = new Info(metrics.timers.ellapsedWindowLoadToRequire, '[main->renderer]', StartupKindToString(metrics.windowKind)); table['require(workbench.main.js)'] = new Info(metrics.timers.ellapsedRequire, '[renderer]', `cached data: ${(metrics.didUseCachedData ? 'YES' : 'NO')}${nodeModuleLoadTime ? `, node_modules took ${nodeModuleLoadTime}ms` : ''}`); - table['init workspace storage'] = new Info(metrics.timers.ellapsedWorkspaceStorageInit, '[renderer]'); + table['require workspace storage'] = new Info(metrics.timers.ellapsedWorkspaceStorageRequire, '[renderer]'); + table['require & init workspace storage'] = new Info(metrics.timers.ellapsedWorkspaceStorageInit, '[renderer]'); table['register extensions & spawn extension host'] = new Info(metrics.timers.ellapsedExtensions, '[renderer]'); table['restore viewlet'] = new Info(metrics.timers.ellapsedViewletRestore, '[renderer]', metrics.viewletId); diff --git a/src/vs/workbench/services/timer/electron-browser/timerService.ts b/src/vs/workbench/services/timer/electron-browser/timerService.ts index c69fa9b6dcc..9f946feb242 100644 --- a/src/vs/workbench/services/timer/electron-browser/timerService.ts +++ b/src/vs/workbench/services/timer/electron-browser/timerService.ts @@ -53,6 +53,7 @@ export interface IMemoryInfo { "timers.ellapsedExtensions" : { "classification": "SystemMetaData", "purpose": "PerformanceAndHealth", "isMeasurement": true }, "timers.ellapsedExtensionsReady" : { "classification": "SystemMetaData", "purpose": "PerformanceAndHealth", "isMeasurement": true }, "timers.ellapsedRequire" : { "classification": "SystemMetaData", "purpose": "PerformanceAndHealth", "isMeasurement": true }, + "timers.ellapsedWorkspaceStorageRequire" : { "classification": "SystemMetaData", "purpose": "PerformanceAndHealth", "isMeasurement": true }, "timers.ellapsedWorkspaceStorageInit" : { "classification": "SystemMetaData", "purpose": "PerformanceAndHealth", "isMeasurement": true }, "timers.ellapsedViewletRestore" : { "classification": "SystemMetaData", "purpose": "PerformanceAndHealth", "isMeasurement": true }, "timers.ellapsedPanelRestore" : { "classification": "SystemMetaData", "purpose": "PerformanceAndHealth", "isMeasurement": true }, @@ -194,7 +195,16 @@ export interface IStartupMetrics { ellapsedWindowLoadToRequire: number; /** - * The time it took to connect to the workspace storage DB and load the initial set of values. + * The time it took to require the workspace storage DB. + * + * * Happens in the renderer-process + * * Measured with the `willRequireSQLite` and `didRequireSQLite` performance marks. + */ + ellapsedWorkspaceStorageRequire: number; + + /** + * The time it took to require the workspace storage DB, connect to it + * and load the initial set of values. * * * Happens in the renderer-process * * Measured with the `willInitWorkspaceStorage` and `didInitWorkspaceStorage` performance marks. @@ -378,6 +388,7 @@ class TimerService implements ITimerService { ellapsedWindowLoad: initialStartup ? perf.getDuration('main:appReady', 'main:loadWindow') : undefined, ellapsedWindowLoadToRequire: perf.getDuration('main:loadWindow', 'willLoadWorkbenchMain'), ellapsedRequire: perf.getDuration('willLoadWorkbenchMain', 'didLoadWorkbenchMain'), + ellapsedWorkspaceStorageRequire: perf.getDuration('willRequireSQLite', 'didRequireSQLite'), ellapsedWorkspaceStorageInit: perf.getDuration('willInitWorkspaceStorage', 'didInitWorkspaceStorage'), ellapsedExtensions: perf.getDuration('willLoadExtensions', 'didLoadExtensions'), ellapsedEditorRestore: perf.getDuration('willRestoreEditors', 'didRestoreEditors'),