#56950 - add search telemetry for EH-based search

src/vs/workbench/api/node/extHostSearch.fileIndex.ts

@@ -10,12 +10,14 @@ import { CancellationTokenSource } from 'vs/base/common/cancellation';
 import { toErrorMessage } from 'vs/base/common/errorMessage';
 import * as glob from 'vs/base/common/glob';
 import * as resources from 'vs/base/common/resources';
+import { StopWatch } from 'vs/base/common/stopwatch';
 import * as strings from 'vs/base/common/strings';
 import URI from 'vs/base/common/uri';
 import { TPromise } from 'vs/base/common/winjs.base';
 import { compareItemsByScore, IItemAccessor, prepareQuery, ScorerCache } from 'vs/base/parts/quickopen/common/quickOpenScorer';
-import { IFileMatch, IFolderQuery, IRawSearchQuery, ISearchCompleteStats, ISearchQuery } from 'vs/platform/search/common/search';
+import { ICachedSearchStats, IFileMatch, IFolderQuery, IRawSearchQuery, ISearchCompleteStats, ISearchQuery, IFileSearchStats, IFileIndexProviderStats } from 'vs/platform/search/common/search';
 import * as vscode from 'vscode';
+import { canceled } from 'vs/base/common/errors';
 
 export interface IInternalFileMatch {
 	base: URI;
@@ -135,10 +137,10 @@ export interface IDirectoryTree {
 	pathToEntries: { [relativePath: string]: IDirectoryEntry[] };
 }
 
-// ???
-interface IInternalSearchComplete {
+interface IInternalSearchComplete<T = IFileSearchStats> {
 	limitHit: boolean;
 	results: IInternalFileMatch[];
+	stats: T;
 }
 
 export class FileIndexSearchEngine {
@@ -151,6 +153,9 @@ export class FileIndexSearchEngine {
 	private resultCount: number;
 	private isCanceled: boolean;
 
+	private filesWalked = 0;
+	private dirsWalked = 0;
+
 	private activeCancellationTokens: Set<CancellationTokenSource>;
 
 	private globalExcludePattern: glob.ParsedExpression;
@@ -177,21 +182,22 @@ export class FileIndexSearchEngine {
 		this.activeCancellationTokens = new Set();
 	}
 
-	public search(_onResult: (match: IInternalFileMatch) => void): TPromise<{ isLimitHit: boolean }> {
+	public search(_onResult: (match: IInternalFileMatch) => void): TPromise<{ isLimitHit: boolean, stats: IFileIndexProviderStats }> {
 		if (this.config.folderQueries.length !== 1) {
 			throw new Error('Searches just one folder');
 		}
 
+		// Searches a single folder
 		const folderQuery = this.config.folderQueries[0];
 
-		return new TPromise<{ isLimitHit: boolean }>((resolve, reject) => {
+		return new TPromise<{ isLimitHit: boolean, stats: IFileIndexProviderStats }>((resolve, reject) => {
 			const onResult = (match: IInternalFileMatch) => {
 				this.resultCount++;
 				_onResult(match);
 			};
 
 			if (this.isCanceled) {
-				return resolve({ isLimitHit: this.isLimitHit });
+				throw canceled();
 			}
 
 			// For each extra file
@@ -210,8 +216,11 @@ export class FileIndexSearchEngine {
 			}
 
 			return this.searchInFolder(folderQuery, _onResult)
-				.then(() => {
-					resolve({ isLimitHit: this.isLimitHit });
+				.then(stats => {
+					resolve({
+						isLimitHit: this.isLimitHit,
+						stats
+					});
 				}, (errs: Error[]) => {
 					const errMsg = errs
 						.map(err => toErrorMessage(err))
@@ -222,7 +231,7 @@ export class FileIndexSearchEngine {
 		});
 	}
 
-	private searchInFolder(fq: IFolderQuery<URI>, onResult: (match: IInternalFileMatch) => void): TPromise<void> {
+	private searchInFolder(fq: IFolderQuery<URI>, onResult: (match: IInternalFileMatch) => void): TPromise<IFileIndexProviderStats> {
 		let cancellation = new CancellationTokenSource();
 		return new TPromise((resolve, reject) => {
 			const options = this.getSearchOptionsForFolder(fq);
@@ -249,12 +258,18 @@ export class FileIndexSearchEngine {
 				this.addDirectoryEntries(tree, fq.folder, relativePath, onResult);
 			};
 
+			let providerSW: StopWatch;
+			let providerTime: number;
+			let fileWalkTime: number;
 			new TPromise(resolve => process.nextTick(resolve))
 				.then(() => {
 					this.activeCancellationTokens.add(cancellation);
+					providerSW = StopWatch.create();
 					return this.provider.provideFileIndex(options, cancellation.token);
 				})
 				.then(results => {
+					providerTime = providerSW.elapsed();
+					const postProcessSW = StopWatch.create();
 					this.activeCancellationTokens.delete(cancellation);
 					if (this.isCanceled) {
 						return null;
@@ -263,11 +278,17 @@ export class FileIndexSearchEngine {
 					results.forEach(onProviderResult);
 
 					this.matchDirectoryTree(tree, queryTester, onResult);
+					fileWalkTime = postProcessSW.elapsed();
 					return null;
 				}).then(
 					() => {
 						cancellation.dispose();
-						resolve(undefined);
+						resolve(<IFileIndexProviderStats>{
+							providerTime,
+							fileWalkTime,
+							directoriesWalked: this.dirsWalked,
+							filesWalked: this.filesWalked
+						});
 					},
 					err => {
 						cancellation.dispose();
@@ -327,7 +348,7 @@ export class FileIndexSearchEngine {
 		const self = this;
 		const filePattern = this.filePattern;
 		function matchDirectory(entries: IDirectoryEntry[]) {
-			// self.directoriesWalked++;
+			self.dirsWalked++;
 			for (let i = 0, n = entries.length; i < n; i++) {
 				const entry = entries[i];
 				const { relativePath, basename } = entry;
@@ -345,7 +366,7 @@ export class FileIndexSearchEngine {
 				if (sub) {
 					matchDirectory(sub);
 				} else {
-					// self.filesWalked++;
+					self.filesWalked++;
 					if (relativePath === filePattern) {
 						continue; // ignore file if its path matches with the file pattern because that is already matched above
 					}
@@ -427,7 +448,13 @@ export class FileIndexSearchManager {
 			.then(complete => {
 				this.sendAsBatches(complete.results, onBatch, FileIndexSearchManager.BATCH_SIZE);
 				return <ISearchCompleteStats>{
-					limitHit: complete.limitHit
+					limitHit: complete.limitHit,
+					stats: {
+						type: 'fileIndexProver',
+						detailStats: complete.stats,
+						fromCache: false,
+						resultCount: complete.results.length
+					}
 				};
 			});
 	}
@@ -452,7 +479,7 @@ export class FileIndexSearchManager {
 
 	private doSortedSearch(engine: FileIndexSearchEngine, config: ISearchQuery): TPromise<IInternalSearchComplete> {
 		let searchPromise: TPromise<void>;
-		let allResultsPromise = new TPromise<IInternalSearchComplete>((c, e) => {
+		let allResultsPromise = new TPromise<IInternalSearchComplete<IFileIndexProviderStats>>((c, e) => {
 			searchPromise = this.doSearch(engine).then(c, e);
 		}, () => {
 			searchPromise.cancel();
@@ -462,8 +489,14 @@ export class FileIndexSearchManager {
 		let cache: Cache;
 		if (folderCacheKey) {
 			cache = this.getOrCreateCache(folderCacheKey);
-			cache.resultsToSearchCache[config.filePattern] = allResultsPromise;
-			allResultsPromise.then(null, err => {
+			const cacheRow: ICacheRow = {
+				promise: allResultsPromise,
+				resolved: false
+			};
+			cache.resultsToSearchCache[config.filePattern] = cacheRow;
+			allResultsPromise.then(() => {
+				cacheRow.resolved = true;
+			}, err => {
 				delete cache.resultsToSearchCache[config.filePattern];
 			});
 			allResultsPromise = this.preventCancellation(allResultsPromise);
@@ -473,12 +506,22 @@ export class FileIndexSearchManager {
 		return new TPromise<IInternalSearchComplete>((c, e) => {
 			chained = allResultsPromise.then(complete => {
 				const scorerCache: ScorerCache = cache ? cache.scorerCache : Object.create(null);
+				const sortSW = (typeof config.maxResults !== 'number' || config.maxResults > 0) && StopWatch.create();
 				return this.sortResults(config, complete.results, scorerCache)
 					.then(sortedResults => {
-
-						c({
+						// sortingTime: -1 indicates a "sorted" search that was not sorted, i.e. populating the cache when quickopen is opened.
+						// Contrasting with findFiles which is not sorted and will have sortingTime: undefined
+						const sortingTime = sortSW ? sortSW.elapsed() : -1;
+						c(<IInternalSearchComplete>{
 							limitHit: complete.limitHit || typeof config.maxResults === 'number' && complete.results.length > config.maxResults, // ??
-							results: sortedResults
+							results: sortedResults,
+							stats: {
+								detailStats: complete.stats,
+								fromCache: false,
+								resultCount: sortedResults.length,
+								sortingTime,
+								type: 'fileIndexProver'
+							}
 						});
 					});
 			}, e);
@@ -507,11 +550,19 @@ export class FileIndexSearchManager {
 			let chained: TPromise<void>;
 			return new TPromise<IInternalSearchComplete>((c, e) => {
 				chained = cached.then(complete => {
+					const sortSW = StopWatch.create();
 					return this.sortResults(config, complete.results, cache.scorerCache)
 						.then(sortedResults => {
-							c({
+							c(<IInternalSearchComplete<IFileSearchStats>>{
 								limitHit: complete.limitHit || typeof config.maxResults === 'number' && complete.results.length > config.maxResults,
-								results: sortedResults
+								results: sortedResults,
+								stats: {
+									fromCache: true,
+									detailStats: complete.stats,
+									type: 'fileIndexProver',
+									resultCount: sortedResults.length,
+									sortingTime: sortSW.elapsed()
+								}
 							});
 						});
 				}, e);
@@ -544,14 +595,16 @@ export class FileIndexSearchManager {
 		}
 	}
 
-	private getResultsFromCache(cache: Cache, searchValue: string): TPromise<IInternalSearchComplete> {
+	private getResultsFromCache(cache: Cache, searchValue: string): TPromise<IInternalSearchComplete<ICachedSearchStats>> {
+		const cacheLookupSW = StopWatch.create();
+
 		if (path.isAbsolute(searchValue)) {
 			return null; // bypass cache if user looks up an absolute path where matching goes directly on disk
 		}
 
 		// Find cache entries by prefix of search value
 		const hasPathSep = searchValue.indexOf(path.sep) >= 0;
-		let cached: TPromise<IInternalSearchComplete>;
+		let cacheRow: ICacheRow;
 		for (let previousSearch in cache.resultsToSearchCache) {
 
 			// If we narrow down, we might be able to reuse the cached results
@@ -560,18 +613,24 @@ export class FileIndexSearchManager {
 					continue; // since a path character widens the search for potential more matches, require it in previous search too
 				}
 
-				const c = cache.resultsToSearchCache[previousSearch];
-				cached = this.preventCancellation(c);
+				const row = cache.resultsToSearchCache[previousSearch];
+				cacheRow = {
+					promise: this.preventCancellation(row.promise),
+					resolved: row.resolved
+				};
 				break;
 			}
 		}
 
-		if (!cached) {
+		if (!cacheRow) {
 			return null;
 		}
 
-		return new TPromise<IInternalSearchComplete>((c, e) => {
-			cached.then(complete => {
+		const cacheLookupTime = cacheLookupSW.elapsed();
+		const cacheFilterSW = StopWatch.create();
+
+		return new TPromise<IInternalSearchComplete<ICachedSearchStats>>((c, e) => {
+			cacheRow.promise.then(complete => {
 				// Pattern match on results
 				let results: IInternalFileMatch[] = [];
 				const normalizedSearchValueLowercase = strings.stripWildcards(searchValue).toLowerCase();
@@ -586,24 +645,31 @@ export class FileIndexSearchManager {
 					results.push(entry);
 				}
 
-				c({
+				c(<IInternalSearchComplete<ICachedSearchStats>>{
 					limitHit: complete.limitHit,
-					results
+					results,
+					stats: {
+						cacheWasResolved: cacheRow.resolved,
+						cacheLookupTime,
+						cacheFilterTime: cacheFilterSW.elapsed(),
+						cacheEntryCount: complete.results.length
+					}
 				});
 			}, e);
 		}, () => {
-			cached.cancel();
+			cacheRow.promise.cancel();
 		});
 	}
 
-	private doSearch(engine: FileIndexSearchEngine): TPromise<IInternalSearchComplete> {
+	private doSearch(engine: FileIndexSearchEngine): TPromise<IInternalSearchComplete<IFileIndexProviderStats>> {
 		const results: IInternalFileMatch[] = [];
 		const onResult = match => results.push(match);
-		return new TPromise<IInternalSearchComplete>((c, e) => {
+		return new TPromise<IInternalSearchComplete<IFileIndexProviderStats>>((c, e) => {
 			engine.search(onResult).then(result => {
-				c({
+				c(<IInternalSearchComplete<IFileIndexProviderStats>>{
 					limitHit: result.isLimitHit,
-					results
+					results,
+					stats: result.stats
 				});
 			}, e);
 		}, () => {
@@ -636,9 +702,14 @@ export class FileIndexSearchManager {
 	}
 }
 
+interface ICacheRow {
+	promise: TPromise<IInternalSearchComplete<IFileIndexProviderStats>>;
+	resolved: boolean;
+}
+
 class Cache {
 
-	public resultsToSearchCache: { [searchValue: string]: TPromise<IInternalSearchComplete>; } = Object.create(null);
+	public resultsToSearchCache: { [searchValue: string]: ICacheRow; } = Object.create(null);
 
 	public scorerCache: ScorerCache = Object.create(null);
 }

src/vs/workbench/api/node/extHostSearch.ts

@@ -12,11 +12,13 @@ import * as resources from 'vs/base/common/resources';
 import URI, { UriComponents } from 'vs/base/common/uri';
 import { TPromise } from 'vs/base/common/winjs.base';
 import * as extfs from 'vs/base/node/extfs';
-import { IFileMatch, IFolderQuery, IPatternInfo, IRawSearchQuery, ISearchCompleteStats, ISearchQuery } from 'vs/platform/search/common/search';
+import { IFileMatch, IFolderQuery, IPatternInfo, IRawSearchQuery, ISearchCompleteStats, ISearchQuery, IFileSearchProviderStats } from 'vs/platform/search/common/search';
 import * as vscode from 'vscode';
 import { ExtHostSearchShape, IMainContext, MainContext, MainThreadSearchShape } from './extHost.protocol';
 import { toDisposable } from 'vs/base/common/lifecycle';
 import { IInternalFileMatch, QueryGlobTester, resolvePatternsForProvider, IDirectoryTree, IDirectoryEntry, FileIndexSearchManager } from 'vs/workbench/api/node/extHostSearch.fileIndex';
+import { StopWatch } from 'vs/base/common/stopwatch';
+import { isPromiseCanceledError } from 'vs/base/common/errors';
 
 export interface ISchemeTransformer {
 	transformOutgoing(scheme: string): string;
@@ -84,7 +86,11 @@ export class ExtHostSearch implements ExtHostSearchShape {
 			return new TPromise((c, e) => {
 				this._fileSearchManager.fileSearch(query, provider, batch => {
 					this._proxy.$handleFileMatch(handle, session, batch.map(p => p.resource));
-				}, cancelSource.token).then(c, e);
+				}, cancelSource.token).then(c, err => {
+					if (!isPromiseCanceledError(err)) {
+						e(err);
+					}
+				});
 			}, () => {
 				// TODO IPC promise cancellation #53526
 				cancelSource.cancel();
@@ -95,6 +101,12 @@ export class ExtHostSearch implements ExtHostSearchShape {
 			if (indexProvider) {
 				return this._fileIndexSearchManager.fileSearch(query, indexProvider, batch => {
 					this._proxy.$handleFileMatch(handle, session, batch.map(p => p.resource));
+				}).then(null, err => {
+					if (!isPromiseCanceledError(err)) {
+						throw err;
+					}
+
+					return null;
 				});
 			} else {
 				throw new Error('something went wrong');
@@ -474,8 +486,11 @@ class FileSearchEngine {
 			// For each root folder
 			TPromise.join(folderQueries.map(fq => {
 				return this.searchInFolder(fq, onResult);
-			})).then(() => {
-				resolve({ limitHit: this.isLimitHit });
+			})).then(stats => {
+				resolve({
+					limitHit: this.isLimitHit,
+					stats: stats[0] // Only looking at single-folder workspace stats...
+				});
 			}, (errs: Error[]) => {
 				const errMsg = errs
 					.map(err => toErrorMessage(err))
@@ -486,7 +501,7 @@ class FileSearchEngine {
 		});
 	}
 
-	private searchInFolder(fq: IFolderQuery<URI>, onResult: (match: IInternalFileMatch) => void): TPromise<void> {
+	private searchInFolder(fq: IFolderQuery<URI>, onResult: (match: IInternalFileMatch) => void): TPromise<IFileSearchProviderStats> {
 		let cancellation = new CancellationTokenSource();
 		return new TPromise((resolve, reject) => {
 			const options = this.getSearchOptionsForFolder(fq);
@@ -495,10 +510,12 @@ class FileSearchEngine {
 			const queryTester = new QueryGlobTester(this.config, fq);
 			const noSiblingsClauses = !queryTester.hasSiblingExcludeClauses();
 
+			let providerSW: StopWatch;
 			new TPromise(_resolve => process.nextTick(_resolve))
 				.then(() => {
 					this.activeCancellationTokens.add(cancellation);
 
+					providerSW = StopWatch.create();
 					return this.provider.provideFileSearchResults(
 						{
 							pattern: this.config.filePattern || ''
@@ -507,8 +524,11 @@ class FileSearchEngine {
 						cancellation.token);
 				})
 				.then(results => {
+					const providerTime = providerSW.elapsed();
+					const postProcessSW = StopWatch.create();
+
 					if (this.isCanceled) {
-						return;
+						return null;
 					}
 
 					if (results) {
@@ -533,11 +553,14 @@ class FileSearchEngine {
 					}
 
 					this.matchDirectoryTree(tree, queryTester, onResult);
-					return null;
+					return <IFileSearchProviderStats>{
+						providerTime,
+						postProcessTime: postProcessSW.elapsed()
+					};
 				}).then(
-					() => {
+					stats => {
 						cancellation.dispose();
-						resolve(null);
+						resolve(stats);
 					},
 					err => {
 						cancellation.dispose();
@@ -646,6 +669,7 @@ class FileSearchEngine {
 
 interface IInternalSearchComplete {
 	limitHit: boolean;
+	stats?: IFileSearchProviderStats;
 }
 
 class FileSearchManager {
@@ -655,14 +679,22 @@ class FileSearchManager {
 	fileSearch(config: ISearchQuery, provider: vscode.FileSearchProvider, onBatch: (matches: IFileMatch[]) => void, token: CancellationToken): TPromise<ISearchCompleteStats> {
 		const engine = new FileSearchEngine(config, provider);
 
+		let resultCount = 0;
 		const onInternalResult = (batch: IInternalFileMatch[]) => {
+			resultCount += batch.length;
 			onBatch(batch.map(m => this.rawMatchToSearchItem(m)));
 		};
 
 		return this.doSearch(engine, FileSearchManager.BATCH_SIZE, onInternalResult, token).then(
 			result => {
-				return {
-					limitHit: result.limitHit
+				return <ISearchCompleteStats>{
+					limitHit: result.limitHit,
+					stats: {
+						fromCache: false,
+						type: 'fileSearchProvider',
+						resultCount,
+						detailStats: result.stats
+					}
 				};
 			});
 	}