remove timedPublicLog 🔥

fixes #11678

src/vs/editor/contrib/quickFix/browser/quickFixSelectionWidget.ts

@@ -8,7 +8,6 @@
 import 'vs/css!./quickFix';
 import * as nls from 'vs/nls';
 import {illegalArgument, onUnexpectedError} from 'vs/base/common/errors';
-import * as timer from 'vs/base/common/timer';
 import {TPromise} from 'vs/base/common/winjs.base';
 import * as dom from 'vs/base/browser/dom';
 import {IMouseEvent} from 'vs/base/browser/mouseEvent';
@@ -337,12 +336,10 @@ export class QuickFixSelectionWidget implements IContentWidget {
 		this.releaseModel();
 		this.model = newModel;
 
-		var timer: timer.ITimerEvent = null,
-			loadingHandle: number;
+		var loadingHandle: number;
 
 		this.modelListenersToRemove.push(this.model.addListener2('loading', (e: any) => {
 			if (!this.isActive) {
-				timer = this.telemetryService.timedPublicLog('QuickFixSelectionWidgetLoadingTime');
 				this.isLoading = true;
 				this.isAuto = !!e.auto;
 
@@ -397,12 +394,6 @@ export class QuickFixSelectionWidget implements IContentWidget {
 			this.telemetryData = this.telemetryData || {};
 			this.telemetryData.suggestionCount = fixes.length;
 			this.telemetryData.suggestedIndex = bestFixIndex;
-
-			if (timer) {
-				timer.data = { reason: 'results' };
-				timer.stop();
-				timer = null;
-			}
 		}));
 
 		this.modelListenersToRemove.push(this.model.addListener2('empty', (e: { auto: boolean; }) => {
@@ -428,12 +419,6 @@ export class QuickFixSelectionWidget implements IContentWidget {
 			} else {
 				dom.addClass(this.domnode, 'empty');
 			}
-
-			if (timer) {
-				timer.data = { reason: 'empty' };
-				timer.stop();
-				timer = null;
-			}
 		}));
 
 		this.modelListenersToRemove.push(this.model.addListener2('cancel', (e: any) => {
@@ -453,12 +438,6 @@ export class QuickFixSelectionWidget implements IContentWidget {
 					this.submitTelemetryData();
 				}
 			}
-
-			if (timer) {
-				timer.data = { reason: 'cancel' };
-				timer.stop();
-				timer = null;
-			}
 		}));
 	}
 

src/vs/editor/contrib/referenceSearch/browser/referencesController.ts

@@ -10,6 +10,7 @@ import {IDisposable, dispose} from 'vs/base/common/lifecycle';
 import Severity from 'vs/base/common/severity';
 import {TPromise} from 'vs/base/common/winjs.base';
 import {IEditorService} from 'vs/platform/editor/common/editor';
+import { fromPromise, stopwatch } from 'vs/base/common/event';
 import {IInstantiationService, optional} from 'vs/platform/instantiation/common/instantiation';
 import {IContextKey, IContextKeyService, RawContextKey} from 'vs/platform/contextkey/common/contextkey';
 import {IMessageService} from 'vs/platform/message/common/message';
@@ -137,11 +138,8 @@ export class ReferencesController implements editorCommon.IEditorContribution {
 		}));
 
 		const requestId = ++this._requestIdPool;
-		const timer = this._telemetryService.timedPublicLog('findReferences', {
-			mode: this._editor.getModel().getMode().getId()
-		});
 
-		modelPromise.then(model => {
+		const promise = modelPromise.then(model => {
 
 			// still current request? widget still open?
 			if (requestId !== this._requestIdPool || !this._widget) {
@@ -177,10 +175,14 @@ export class ReferencesController implements editorCommon.IEditorContribution {
 
 		}, error => {
 			this._messageService.show(Severity.Error, error);
-
-		}).done(() => {
-			timer.stop();
 		});
+
+		const onDone = stopwatch(fromPromise(promise));
+
+		onDone(duration => this._telemetryService.publicLog('findReferences', {
+			duration,
+			mode: this._editor.getModel().getMode().getId()
+		}));
 	}
 
 	public closeWidget(): void {

src/vs/platform/telemetry/common/telemetry.ts

@@ -5,7 +5,6 @@
 'use strict';
 
 import {TPromise} from 'vs/base/common/winjs.base';
-import {ITimerEvent, nullEvent} from 'vs/base/common/timer';
 import {createDecorator} from 'vs/platform/instantiation/common/instantiation';
 
 export const ITelemetryService = createDecorator<ITelemetryService>('telemetryService');
@@ -26,11 +25,6 @@ export interface ITelemetryService {
 	 */
 	publicLog(eventName: string, data?: any): TPromise<void>;
 
-	/**
-	 * Starts a telemetry timer. Call stop() to send the event.
-	 */
-	timedPublicLog(name: string, data?: any): ITimerEvent;
-
 	getTelemetryInfo(): TPromise<ITelemetryInfo>;
 
 	isOptedIn: boolean;
@@ -38,9 +32,6 @@ export interface ITelemetryService {
 
 export const NullTelemetryService: ITelemetryService = {
 	_serviceBrand: undefined,
-	timedPublicLog(name: string, data?: any) {
-		return nullEvent;
-	},
 	publicLog(eventName: string, data?: any) {
 		return TPromise.as<void>(null);
 	},

src/vs/platform/telemetry/common/telemetryService.ts

@@ -13,7 +13,6 @@ import {IConfigurationService} from 'vs/platform/configuration/common/configurat
 import {IConfigurationRegistry, Extensions} from 'vs/platform/configuration/common/configurationRegistry';
 import {TPromise} from 'vs/base/common/winjs.base';
 import {IDisposable, dispose} from 'vs/base/common/lifecycle';
-import {TimeKeeper, ITimerEvent} from 'vs/base/common/timer';
 import {cloneAndChange, mixin} from 'vs/base/common/objects';
 import {Registry} from 'vs/platform/platform';
 
@@ -37,7 +36,6 @@ export class TelemetryService implements ITelemetryService {
 	private _userOptIn: boolean;
 
 	private _disposables: IDisposable[] = [];
-	private _timeKeeper: TimeKeeper;
 	private _cleanupPatterns: [RegExp, string][] = [];
 
 	constructor(
@@ -62,10 +60,6 @@ export class TelemetryService implements ITelemetryService {
 			[/ENOENT: no such file or directory.*?\'([^\']+)\'/gi, 'ENOENT: no such file or directory']
 		);
 
-		this._timeKeeper = new TimeKeeper();
-		this._disposables.push(this._timeKeeper);
-		this._disposables.push(this._timeKeeper.addListener(events => this._onTelemetryTimerEventStop(events)));
-
 		if (this._configurationService) {
 			this._updateUserOptIn();
 			this._configurationService.onDidUpdateConfiguration(this._updateUserOptIn, this, this._disposables);
@@ -78,15 +72,6 @@ export class TelemetryService implements ITelemetryService {
 		this._userOptIn = config ? config.enableTelemetry : this._userOptIn;
 	}
 
-	private _onTelemetryTimerEventStop(events: ITimerEvent[]): void {
-		for (let i = 0; i < events.length; i++) {
-			let event = events[i];
-			let data = event.data || {};
-			data.duration = event.timeTaken();
-			this.publicLog(event.name, data);
-		}
-	}
-
 	get isOptedIn(): boolean {
 		return this._userOptIn;
 	}
@@ -106,15 +91,6 @@ export class TelemetryService implements ITelemetryService {
 		this._disposables = dispose(this._disposables);
 	}
 
-	timedPublicLog(name: string, data?: any): ITimerEvent {
-		let topic = 'public';
-		let event = this._timeKeeper.start(topic, name);
-		if (data) {
-			event.data = data;
-		}
-		return event;
-	}
-
 	publicLog(eventName: string, data?: any): TPromise<any> {
 		// don't send events when the user is optout unless the event is the opt{in|out} signal
 		if (!this._userOptIn && eventName !== 'optInStatus') {

src/vs/platform/telemetry/test/node/telemetryService.test.ts

@@ -11,7 +11,6 @@ import {TelemetryService} from 'vs/platform/telemetry/common/telemetryService';
 import ErrorTelemetry from 'vs/platform/telemetry/browser/errorTelemetry';
 import Telemetry = require('vs/platform/telemetry/common/telemetry');
 import Errors = require('vs/base/common/errors');
-import Timer = require('vs/base/common/timer');
 import * as sinon from 'sinon';
 import {getConfigurationValue} from 'vs/platform/configuration/common/configuration';
 
@@ -192,40 +191,6 @@ suite('TelemetryService', () => {
 		});
 	});
 
-	test('Telemetry Timer events', sinon.test(function () {
-		Timer.ENABLE_TIMER = true;
-
-		let testAppender = new TestTelemetryAppender();
-		let service = new TelemetryService({ appender: testAppender }, undefined);
-
-		let t1 = service.timedPublicLog('editorDance');
-		this.clock.tick(20);
-		let t2 = service.timedPublicLog('editorSwoon', null);
-		this.clock.tick(20);
-
-		t1.stop(new Date());
-		t2.stop(new Date());
-
-		let t3 = service.timedPublicLog('editorMove', { someData: 'data' });
-		this.clock.tick(30);
-		t3.stop(new Date());
-
-		assert.equal(testAppender.getEventsCount(), 3);
-
-		assert.equal(testAppender.events[0].eventName, 'editorDance');
-		assert.equal(testAppender.events[0].data.duration, 40);
-
-		assert.equal(testAppender.events[1].eventName, 'editorSwoon');
-		assert.equal(testAppender.events[1].data.duration, 20);
-
-		assert.equal(testAppender.events[2].eventName, 'editorMove');
-		assert.equal(testAppender.events[2].data.duration, 30);
-		assert.equal(testAppender.events[2].data.someData, 'data');
-
-		service.dispose();
-		Timer.ENABLE_TIMER = false;
-	}));
-
 	test('enableTelemetry on by default', sinon.test(function () {
 		let testAppender = new TestTelemetryAppender();
 		let service = new TelemetryService({ appender: testAppender }, undefined);

src/vs/workbench/parts/files/browser/editors/textFileEditor.ts

@@ -64,7 +64,7 @@ export class TextFileEditor extends BaseTextEditor {
 		@IThemeService themeService: IThemeService
 	) {
 		super(TextFileEditor.ID, telemetryService, instantiationService, contextService, storageService, messageService, configurationService, eventService, editorService, themeService);
-		
+
 		// Since we are the one providing save-support for models, we hook up the error handler for saving
 		TextFileEditorModel.setSaveErrorHandler(instantiationService.createInstance(SaveErrorHandler));
 
@@ -135,20 +135,10 @@ export class TextFileEditor extends BaseTextEditor {
 				return null;
 			}
 
-			// log the time it takes the editor to render the resource
-			const mode = textFileModel.textEditorModel.getMode();
-			const setModelEvent = this.telemetryService.timedPublicLog('editorSetModel', {
-				mode: mode && mode.getId(),
-				resource: textFileModel.textEditorModel.uri.toString(),
-			});
-
 			// Editor
 			const textEditor = this.getControl();
 			textEditor.setModel(textFileModel.textEditorModel);
 
-			// stop the event
-			setModelEvent.stop();
-
 			// TextOptions (avoiding instanceof here for a reason, do not change!)
 			let optionsGotApplied = false;
 			if (options && types.isFunction((<TextEditorOptions>options).apply)) {

src/vs/workbench/parts/git/node/rawGitService.ts

@@ -10,7 +10,7 @@ import { detectMimesFromFile, detectMimesFromStream } from 'vs/base/node/mime';
 import { realpath, exists} from 'vs/base/node/pfs';
 import { Repository, GitError } from 'vs/workbench/parts/git/node/git.lib';
 import { IRawGitService, RawServiceState, IRawStatus, IRef, GitErrorCodes, IPushOptions, ICommit } from 'vs/workbench/parts/git/common/git';
-import Event, { Emitter, fromPromise } from 'vs/base/common/event';
+import Event, { Emitter, delayed } from 'vs/base/common/event';
 
 export class RawGitService implements IRawGitService {
 
@@ -207,7 +207,7 @@ export class RawGitService implements IRawGitService {
 
 export class DelayedRawGitService implements IRawGitService {
 	constructor(private raw: TPromise<IRawGitService>){}
-	onOutput: Event<string> = fromPromise(this.raw.then(r => r.onOutput));
+	onOutput: Event<string> = delayed(this.raw.then(r => r.onOutput));
 	getVersion(): TPromise<string> { return this.raw.then(r => r.getVersion()); }
 	serviceState(): TPromise<RawServiceState> { return this.raw.then(r => r.serviceState()); }
 	statusCount(): TPromise<number> { return this.raw.then(r => r.statusCount()); }

src/vs/workbench/parts/search/browser/openAnythingHandler.ts

@@ -141,8 +141,7 @@ export class OpenAnythingHandler extends QuickOpenHandler {
 	}
 
 	public getResults(searchValue: string): TPromise<QuickOpenModel> {
-		const timerEvent = this.telemetryService.timedPublicLog('openAnything');
-		const startTime = timerEvent.startTime ? timerEvent.startTime.getTime() : Date.now(); // startTime is undefined when telemetry is disabled
+		const startTime = Date.now();
 
 		this.cancelPendingSearch();
 		this.isClosed = false; // Treat this call as the handler being in use
@@ -212,7 +211,8 @@ export class OpenAnythingHandler extends QuickOpenHandler {
 					fileSearchStats = (<FileQuickOpenModel>results[1]).stats;
 				}
 
-				timerEvent.data = this.createTimerEventData(startTime, {
+				const duration = new Date().getTime() - startTime;
+				const data = this.createTimerEventData(startTime, {
 					searchLength: searchValue.length,
 					unsortedResultTime,
 					sortedResultTime,
@@ -220,7 +220,8 @@ export class OpenAnythingHandler extends QuickOpenHandler {
 					symbols: { fromCache: false },
 					files: fileSearchStats
 				});
-				timerEvent.stop();
+
+				this.telemetryService.publicLog('openAnything', objects.assign(data, { duration }));
 
 				return TPromise.as<QuickOpenModel>(new QuickOpenModel(viewResults));
 			}, (error: Error) => {

src/vs/workbench/parts/search/common/searchModel.ts

@@ -13,7 +13,7 @@ import { TPromise, PPromise } from 'vs/base/common/winjs.base';
 import URI from 'vs/base/common/uri';
 import { LinkedMap } from 'vs/base/common/map';
 import { ArraySet } from 'vs/base/common/set';
-import Event, { Emitter } from 'vs/base/common/event';
+import Event, { Emitter, fromPromise, stopwatch, any } from 'vs/base/common/event';
 import * as Search from 'vs/platform/search/common/search';
 import { ISearchProgressItem, ISearchComplete, ISearchQuery } from 'vs/platform/search/common/search';
 import { ReplacePattern } from 'vs/platform/search/common/replace';
@@ -360,14 +360,16 @@ export class SearchResult extends Disposable {
 
 	public replaceAll(progressRunner: IProgressRunner): TPromise<any> {
 		this._replacingAll = true;
-		let replaceAllTimer = this.telemetryService.timedPublicLog('replaceAll.started');
-		return this.replaceService.replace(this.matches(), progressRunner).then(() => {
-			replaceAllTimer.stop();
+
+		const promise = this.replaceService.replace(this.matches(), progressRunner);
+		const onDone = stopwatch(fromPromise(promise));
+		onDone(duration => this.telemetryService.publicLog('replaceAll.started', { duration }));
+
+		return promise.then(() => {
 			this._replacingAll = false;
 			this.clear();
 		}, () => {
 			this._replacingAll = false;
-			replaceAllTimer.stop();
 		});
 	}
 
@@ -460,9 +462,6 @@ export class SearchModel extends Disposable {
 	private _replacePattern: ReplacePattern = null;
 
 	private currentRequest: PPromise<ISearchComplete, ISearchProgressItem>;
-	private progressTimer: timer.ITimerEvent;
-	private doneTimer: timer.ITimerEvent;
-	private timerEvent: timer.ITimerEvent;
 
 	constructor( @ISearchService private searchService, @ITelemetryService private telemetryService: ITelemetryService, @IInstantiationService private instantiationService: IInstantiationService) {
 		super();
@@ -504,22 +503,34 @@ export class SearchModel extends Disposable {
 		this._searchResult.query = this._searchQuery.contentPattern;
 		this._replacePattern = new ReplacePattern(this._replaceString, this._searchQuery.contentPattern);
 
-		this.progressTimer = this.telemetryService.timedPublicLog('searchResultsFirstRender');
-		this.doneTimer = this.telemetryService.timedPublicLog('searchResultsFinished');
-		this.timerEvent = timer.start(timer.Topic.WORKBENCH, 'Search');
-
+		const timerEvent = timer.start(timer.Topic.WORKBENCH, 'Search');
 		this.currentRequest = this.searchService.search(this._searchQuery);
-		this.currentRequest.then(value => this.onSearchCompleted(value),
+
+		const onDone = fromPromise(this.currentRequest);
+		const onDoneStopwatch = stopwatch(onDone);
+
+		onDone(() => timerEvent.stop());
+		onDoneStopwatch(duration => this.telemetryService.publicLog('searchResultsFinished', { duration }));
+
+		const progressEmitter = new Emitter<void>();
+		const onFirstRender = any(onDone, progressEmitter.event);
+		const onFirstRenderStopwatch = stopwatch(onFirstRender);
+
+		onFirstRenderStopwatch(duration => this.telemetryService.publicLog('searchResultsFirstRender', { duration }));
+
+		this.currentRequest.then(
+			value => this.onSearchCompleted(value),
 			e => this.onSearchError(e),
-			p => this.onSearchProgress(p));
+			p => {
+				progressEmitter.fire();
+				this.onSearchProgress(p);
+			}
+		);
 
 		return this.currentRequest;
 	}
 
 	private onSearchCompleted(completed: ISearchComplete): ISearchComplete {
-		this.progressTimer.stop();
-		this.timerEvent.stop();
-		this.doneTimer.stop();
 		if (completed) {
 			this._searchResult.add(completed.results, false);
 		}
@@ -530,17 +541,12 @@ export class SearchModel extends Disposable {
 	private onSearchError(e: any): void {
 		if (errors.isPromiseCanceledError(e)) {
 			this.onSearchCompleted(null);
-		} else {
-			this.progressTimer.stop();
-			this.doneTimer.stop();
-			this.timerEvent.stop();
 		}
 	}
 
 	private onSearchProgress(p: ISearchProgressItem): void {
 		if (p.resource) {
 			this._searchResult.add([p], true);
-			this.progressTimer.stop();
 		}
 	}
 

src/vs/workbench/parts/search/test/common/searchModel.test.ts

@@ -119,28 +119,32 @@ suite('SearchModel', () => {
 		assert.deepEqual(['searchResultsShown', {count: 3, fileCount: 2}], target.args[0]);
 	});
 
-	test('Search Model: Search reports timed telemetry on search when progress is not called', function () {
+	test('Search Model: Search reports timed telemetry on search when progress is not called', function (done) {
 		let target2= sinon.spy();
 		stub(nullEvent, 'stop', target2);
 		let target1= sinon.stub().returns(nullEvent);
-		instantiationService.stub(ITelemetryService, 'timedPublicLog', target1);
+		instantiationService.stub(ITelemetryService, 'publicLog', target1);
 
 		instantiationService.stub(ISearchService, 'search',  PPromise.as({results: []}));
 
 		let testObject= instantiationService.createInstance(SearchModel);
-		testObject.search({contentPattern: {pattern: 'somestring'}, type: 1});
+		const result = testObject.search({contentPattern: {pattern: 'somestring'}, type: 1});
+
+		setTimeout(() => {
+			result.done(() => {
+				assert.ok(target1.calledWith('searchResultsFirstRender'));
+				assert.ok(target1.calledWith('searchResultsFinished'));
 
-		assert.ok(target1.calledTwice);
-		assert.ok(target1.calledWith('searchResultsFirstRender'));
-		assert.ok(target1.calledWith('searchResultsFinished'));
-		assert.ok(target2.calledThrice);
+				done();
+			});
+		}, 0);
 	});
 
 	test('Search Model: Search reports timed telemetry on search when progress is called', function (done) {
 		let target2= sinon.spy();
 		stub(nullEvent, 'stop', target2);
 		let target1= sinon.stub().returns(nullEvent);
-		instantiationService.stub(ITelemetryService, 'timedPublicLog', target1);
+		instantiationService.stub(ITelemetryService, 'publicLog', target1);
 
 		let promise= new DeferredPPromise<ISearchComplete, ISearchProgressItem>();
 		instantiationService.stub(ISearchService, 'search',  promise);
@@ -151,21 +155,22 @@ suite('SearchModel', () => {
 		promise.progress(aRawMatch('file://c:/1', aLineMatch('some preview')));
 		promise.complete({results: [], stats: testSearchStats});
 
-		result.done(() => {
-			assert.ok(target1.calledTwice);
-			assert.ok(target1.calledWith('searchResultsFirstRender'));
-			assert.ok(target1.calledWith('searchResultsFinished'));
-			assert.equal(4, target2.callCount);
+		setTimeout(() => {
+			result.done(() => {
+				assert.ok(target1.calledWith('searchResultsFirstRender'));
+				assert.ok(target1.calledWith('searchResultsFinished'));
+				// assert.equal(1, target2.callCount);
 
-			done();
-		});
+				done();
+			});
+		}, 0);
 	});
 
 	test('Search Model: Search reports timed telemetry on search when error is called', function (done) {
 		let target2= sinon.spy();
 		stub(nullEvent, 'stop', target2);
 		let target1= sinon.stub().returns(nullEvent);
-		instantiationService.stub(ITelemetryService, 'timedPublicLog', target1);
+		instantiationService.stub(ITelemetryService, 'publicLog', target1);
 
 		let promise= new DeferredPPromise<ISearchComplete, ISearchProgressItem>();
 		instantiationService.stub(ISearchService, 'search',  promise);
@@ -175,21 +180,22 @@ suite('SearchModel', () => {
 
 		promise.error('error');
 
-		result.done(() => {}, () => {
-			assert.ok(target1.calledTwice);
-			assert.ok(target1.calledWith('searchResultsFirstRender'));
-			assert.ok(target1.calledWith('searchResultsFinished'));
-			assert.ok(target2.calledThrice);
+		setTimeout(() => {
+			result.done(() => {}, () => {
+				assert.ok(target1.calledWith('searchResultsFirstRender'));
+				assert.ok(target1.calledWith('searchResultsFinished'));
+				// assert.ok(target2.calledOnce);
 
-			done();
-		});
+				done();
+			});
+		}, 0);
 	});
 
 	test('Search Model: Search reports timed telemetry on search when error is cancelled error', function (done) {
 		let target2= sinon.spy();
 		stub(nullEvent, 'stop', target2);
 		let target1= sinon.stub().returns(nullEvent);
-		instantiationService.stub(ITelemetryService, 'timedPublicLog', target1);
+		instantiationService.stub(ITelemetryService, 'publicLog', target1);
 
 		let promise= new DeferredPPromise<ISearchComplete, ISearchProgressItem>();
 		instantiationService.stub(ISearchService, 'search',  promise);
@@ -199,13 +205,14 @@ suite('SearchModel', () => {
 
 		promise.cancel();
 
-		result.done(() => {}, () => {
-			assert.ok(target1.calledTwice);
-			assert.ok(target1.calledWith('searchResultsFirstRender'));
-			assert.ok(target1.calledWith('searchResultsFinished'));
-			assert.ok(target2.calledThrice);
-			done();
-		});
+		setTimeout(() => {
+			result.done(() => {}, () => {
+				assert.ok(target1.calledWith('searchResultsFirstRender'));
+				assert.ok(target1.calledWith('searchResultsFinished'));
+				// assert.ok(target2.calledOnce);
+				done();
+			});
+		}, 0);
 	});
 
 	test('Search Model: Search results are cleared during search', function () {

src/vs/workbench/test/browser/parts/quickOpen/quickopen.perf.test.ts

@@ -142,20 +142,10 @@ class TestTelemetryService implements ITelemetryService {
 	public _serviceBrand: any;
 	public isOptedIn = true;
 
-	public events: Timer.ITimerEvent[] = [];
-
-	public timedPublicLog(name: string, data?: any): Timer.ITimerEvent {
-		Timer.ENABLE_TIMER = true;
-		const event = Timer.start('TestTelemetry', name);
-		Timer.ENABLE_TIMER = false;
-		if (data) {
-			event.data = data;
-		}
-		this.events.push(event);
-		return event;
-	}
+	public events: any[] = [];
 
 	public publicLog(eventName: string, data?: any): TPromise<void> {
+		this.events.push({ name: eventName, data: data });
 		return TPromise.as<void>(null);
 	}