storage - telemetry around errors and perf

src/vs/base/node/storage.ts

@@ -58,6 +58,10 @@ export class Storage extends Disposable {
 		this.pendingScheduler = new RunOnceScheduler(() => this.flushPending(), Storage.FLUSH_DELAY);
 	}
 
+	get size(): number {
+		return this.cache.size;
+	}
+
 	init(): Promise<void> {
 		if (this.state !== StorageState.None) {
 			return Promise.resolve(); // either closed or already initialized

src/vs/platform/storage/electron-browser/storageService.ts

@@ -15,6 +15,7 @@ import { startsWith } from 'vs/base/common/strings';
 import { Action } from 'vs/base/common/actions';
 import { IWindowService } from 'vs/platform/windows/common/windows';
 import { localize } from 'vs/nls';
+import { mark } from 'vs/base/common/performance';
 
 export class StorageService extends Disposable implements IStorageService {
 	_serviceBrand: any;
@@ -27,6 +28,23 @@ export class StorageService extends Disposable implements IStorageService {
 	private _onWillSaveState: Emitter<void> = this._register(new Emitter<void>());
 	get onWillSaveState(): Event<void> { return this._onWillSaveState.event; }
 
+	private bufferedStorageErrors: (string | Error)[] = [];
+	private _onStorageError: Emitter<string | Error> = this._register(new Emitter<string | Error>());
+	get onStorageError(): Event<string | Error> {
+		if (Array.isArray(this.bufferedStorageErrors)) {
+			if (this.bufferedStorageErrors.length > 0) {
+				const bufferedStorageErrors = this.bufferedStorageErrors;
+				setTimeout(() => {
+					this._onStorageError.fire(`[startup errors] ${bufferedStorageErrors.join('\n')}`);
+				}, 0);
+			}
+
+			this.bufferedStorageErrors = void 0;
+		}
+
+		return this._onStorageError.event;
+	}
+
 	private globalStorage: Storage;
 	private workspaceStorage: Storage;
 
@@ -40,7 +58,15 @@ export class StorageService extends Disposable implements IStorageService {
 		const loggingOptions: IStorageLoggingOptions = {
 			info: environmentService.verbose || environmentService.logStorage,
 			infoLogger: msg => logService.info(msg),
-			errorLogger: error => logService.error(error)
+			errorLogger: error => {
+				logService.error(error);
+
+				if (Array.isArray(this.bufferedStorageErrors)) {
+					this.bufferedStorageErrors.push(error);
+				} else {
+					this._onStorageError.fire(error);
+				}
+			}
 		};
 
 		const useInMemoryStorage = !!environmentService.extensionTestsPath; // never keep any state when running extension tests
@@ -61,7 +87,13 @@ export class StorageService extends Disposable implements IStorageService {
 	}
 
 	init(): Promise<void> {
-		return Promise.all([this.globalStorage.init(), this.workspaceStorage.init()]).then(() => void 0);
+		mark('willInitGlobalStorage');
+		mark('willInitWorkspaceStorage');
+
+		return Promise.all([
+			this.globalStorage.init().then(() => mark('didInitGlobalStorage')),
+			this.workspaceStorage.init().then(() => mark('didInitWorkspaceStorage'))
+		]).then(() => void 0);
 	}
 
 	get(key: string, scope: StorageScope, fallbackValue?: any): string {
@@ -100,6 +132,10 @@ export class StorageService extends Disposable implements IStorageService {
 		return scope === StorageScope.GLOBAL ? this.globalStorage : this.workspaceStorage;
 	}
 
+	getSize(scope: StorageScope): number {
+		return scope === StorageScope.GLOBAL ? this.globalStorage.size : this.workspaceStorage.size;
+	}
+
 	logStorage(): Promise<void> {
 		return Promise.all([this.globalStorage.getItems(), this.workspaceStorage.getItems()]).then(items => {
 			const safeParse = (value: string) => {
@@ -154,7 +190,7 @@ export class LogStorageAction extends Action {
 	}
 
 	run(): Thenable<void> {
-		this.storageService.logStorage();
+		this.storageService.storage.logStorage();
 
 		return this.windowService.openDevTools();
 	}
@@ -174,8 +210,7 @@ export class DelegatingStorageService extends Disposable implements IStorageServ
 	constructor(
 		@IStorageService private storageService: StorageService,
 		@IStorageLegacyService private storageLegacyService: IStorageLegacyService,
-		@ILogService private logService: ILogService,
-		@IEnvironmentService environmentService: IEnvironmentService
+		@ILogService private logService: ILogService
 	) {
 		super();
 
@@ -196,6 +231,10 @@ export class DelegatingStorageService extends Disposable implements IStorageServ
 		}));
 	}
 
+	get storage(): StorageService {
+		return this.storageService;
+	}
+
 	get(key: string, scope: StorageScope, fallbackValue?: any): string {
 		const localStorageValue = this.storageLegacyService.get(key, this.convertScope(scope), fallbackValue);
 		const dbValue = this.storageService.get(key, scope, localStorageValue);
@@ -268,8 +307,4 @@ export class DelegatingStorageService extends Disposable implements IStorageServ
 	private convertScope(scope: StorageScope): StorageLegacyScope {
 		return scope === StorageScope.GLOBAL ? StorageLegacyScope.GLOBAL : StorageLegacyScope.WORKSPACE;
 	}
-
-	logStorage(): Promise<void> {
-		return this.storageService.logStorage();
-	}
 }
\ No newline at end of file

src/vs/workbench/electron-browser/main.ts

@@ -103,7 +103,7 @@ function openWorkbench(configuration: IWindowConfiguration): Promise<void> {
 	]).then(services => {
 		const workspaceService = services[0];
 		const storageLegacyService = createStorageLegacyService(workspaceService, environmentService);
-		const storageService = new DelegatingStorageService(services[1], storageLegacyService, logService, environmentService);
+		const storageService = new DelegatingStorageService(services[1], storageLegacyService, logService);
 
 		return domContentLoaded().then(() => {
 			perf.mark('willStartWorkbench');

src/vs/workbench/electron-browser/shell.ts

@@ -75,7 +75,8 @@ import { IBroadcastService, BroadcastService } from 'vs/platform/broadcast/elect
 import { HashService } from 'vs/workbench/services/hash/node/hashService';
 import { IHashService } from 'vs/workbench/services/hash/common/hashService';
 import { ILogService } from 'vs/platform/log/common/log';
-import { IStorageService } from 'vs/platform/storage/common/storage';
+import { IStorageService, StorageScope } from 'vs/platform/storage/common/storage';
+import { DelegatingStorageService } from 'vs/platform/storage/electron-browser/storageService';
 import { Event, Emitter } from 'vs/base/common/event';
 import { WORKBENCH_BACKGROUND } from 'vs/workbench/common/theme';
 import { ILocalizationsChannel, LocalizationsChannelClient } from 'vs/platform/localizations/node/localizationsIpc';
@@ -109,7 +110,7 @@ export interface ICoreServices {
 	environmentService: IEnvironmentService;
 	logService: ILogService;
 	storageLegacyService: IStorageLegacyService;
-	storageService: IStorageService;
+	storageService: DelegatingStorageService;
 }
 
 /**
@@ -122,7 +123,7 @@ export class WorkbenchShell extends Disposable {
 	get onShutdown(): Event<ShutdownEvent> { return this._onShutdown.event; }
 
 	private storageLegacyService: IStorageLegacyService;
-	private storageService: IStorageService;
+	private storageService: DelegatingStorageService;
 	private environmentService: IEnvironmentService;
 	private logService: ILogService;
 	private configurationService: IConfigurationService;
@@ -217,6 +218,11 @@ export class WorkbenchShell extends Disposable {
 				// Startup Telemetry
 				this.logStartupTelemetry(startupInfos);
 
+				// Storage Telemetry (TODO@Ben remove me later, including storage errors)
+				if (!this.environmentService.extensionTestsPath) {
+					this.logStorageTelemetry();
+				}
+
 				// Set lifecycle phase to `Runnning For A Bit` after a short delay
 				let eventuallPhaseTimeoutHandle = runWhenIdle(() => {
 					eventuallPhaseTimeoutHandle = void 0;
@@ -277,6 +283,60 @@ export class WorkbenchShell extends Disposable {
 		perf.mark('didStartWorkbench');
 	}
 
+	private logStorageTelemetry(): void {
+		const globalStorageInitDuration = perf.getDuration('willInitGlobalStorage', 'didInitGlobalStorage');
+		const workspaceStorageInitDuration = perf.getDuration('willInitWorkspaceStorage', 'didInitWorkspaceStorage');
+		const workbenchLoadDuration = perf.getDuration('willLoadWorkbenchMain', 'didLoadWorkbenchMain');
+
+		/* __GDPR__
+			"sqliteStorageTimers" : {
+				"globalReadTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true },
+				"workspaceReadTime" : { "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 }
+			}
+		*/
+		this.telemetryService.publicLog('sqliteStorageTimers', {
+			'globalReadTime': globalStorageInitDuration,
+			'workspaceReadTime': workspaceStorageInitDuration,
+			'workbenchRequireTime': workbenchLoadDuration,
+			'globalKeys': this.storageService.storage.getSize(StorageScope.GLOBAL),
+			'workspaceKeys': this.storageService.storage.getSize(StorageScope.WORKSPACE),
+			'startupKind': this.lifecycleService.startupKind
+		});
+
+		// Handle errors (avoid duplicates to reduce spam)
+		const loggedStorageErrors = new Set<string>();
+		this._register(this.storageService.storage.onStorageError(error => {
+			const errorStr = `${error}`;
+
+			if (!loggedStorageErrors.has(errorStr)) {
+				loggedStorageErrors.add(errorStr);
+
+				/* __GDPR__
+					"sqliteStorageError" : {
+						"globalReadTime" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true },
+						"workspaceReadTime" : { "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 },
+						"storageError": { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true }
+					}
+				*/
+				this.telemetryService.publicLog('sqliteStorageError', {
+					'globalReadTime': globalStorageInitDuration,
+					'workspaceReadTime': workspaceStorageInitDuration,
+					'workbenchRequireTime': workbenchLoadDuration,
+					'globalKeys': this.storageService.storage.getSize(StorageScope.GLOBAL),
+					'workspaceKeys': this.storageService.storage.getSize(StorageScope.WORKSPACE),
+					'startupKind': this.lifecycleService.startupKind,
+					'storageError': errorStr
+				});
+			}
+		}));
+	}
+
 	private initServiceCollection(container: HTMLElement): [IInstantiationService, ServiceCollection] {
 		const serviceCollection = new ServiceCollection();
 		serviceCollection.set(IWorkspaceContextService, this.contextService);