send auto profiling stack traces also as error telemetry (#172014)

#170954
microsoft · Jan 23, 2023 · 2b5c4dd · 2b5c4dd
1 parent b87234d
commit 2b5c4dd
Show file tree

Hide file tree

Showing 6 changed files with 60 additions and 20 deletions.
diff --git a/src/vs/platform/profiling/common/profilingModel.ts b/src/vs/platform/profiling/common/profilingModel.ts
@@ -331,8 +331,9 @@ export interface BottomUpSample {
 	selfTime: number;
 	totalTime: number;
 	location: string;
+	absLocation: string;
 	url: string;
-	caller: { percentage: number; location: string }[];
+	caller: { percentage: number; absLocation: string; location: string }[];
 	percentage: number;
 	isSpecial: boolean;
 }
diff --git a/src/vs/platform/profiling/common/profilingTelemetrySpec.ts b/src/vs/platform/profiling/common/profilingTelemetrySpec.ts
@@ -6,6 +6,7 @@
 import { ILogService } from 'vs/platform/log/common/log';
 import { BottomUpSample } from 'vs/platform/profiling/common/profilingModel';
 import { ITelemetryService } from 'vs/platform/telemetry/common/telemetry';
+import { errorHandler } from 'vs/base/common/errors';
 
 type TelemetrySampleData = {
 	selfTime: number;
@@ -37,16 +38,10 @@ export interface SampleData {
 	source: string;
 }
 
-export function reportSample(data: SampleData, telemetryService: ITelemetryService, logService: ILogService): void {
+export function reportSample(data: SampleData, telemetryService: ITelemetryService, logService: ILogService, sendAsErrorTelemtry: boolean): void {
 
 	const { sample, perfBaseline, source } = data;
 
-	// log a fake error with a clearer stack
-	const fakeError = new Error(`[PerfSampleError]|${sample.selfTime}ms`);
-	fakeError.name = 'PerfSampleError';
-	fakeError.stack = `${fakeError.message} by ${data.source} in ${sample.location}\n` + sample.caller.map(c => `\t at ${c.location} (${c.percentage}%)`).join('\n');
-	logService.error(fakeError);
-
 	// send telemetry event
 	telemetryService.publicLog2<TelemetrySampleData, TelemetrySampleDataClassification>(`unresponsive.sample`, {
 		perfBaseline,
@@ -59,4 +54,24 @@ export function reportSample(data: SampleData, telemetryService: ITelemetryServi
 		source
 	});
 
+	// log a fake error with a clearer stack
+	const fakeError = new PerformanceError(data);
+	if (sendAsErrorTelemtry) {
+		errorHandler.onUnexpectedError(fakeError);
+	} else {
+		logService.error(fakeError);
+	}
+}
+
+class PerformanceError extends Error {
+	readonly selfTime: number;
+
+	constructor(data: SampleData) {
+		super('[PerfSampleError]');
+		this.name = 'PerfSampleError';
+		this.selfTime = data.sample.selfTime;
+
+		const trace = [data.sample.absLocation, ...data.sample.caller.map(c => c.absLocation)];
+		this.stack = `${this.message} by ${data.source} in ${data.sample.location}\n\t at ${trace.join('\n\t at ')}`;
+	}
 }
diff --git a/src/vs/platform/profiling/electron-sandbox/profileAnalysisWorker.ts b/src/vs/platform/profiling/electron-sandbox/profileAnalysisWorker.ts
@@ -26,7 +26,7 @@ class ProfileAnalysisWorker implements IRequestHandler, IProfileAnalysisWorker {
 		}
 
 		const model = buildModel(profile);
-		const samples = bottomUp(model, 5, false)
+		const samples = bottomUp(model, 5)
 			.filter(s => !s.isSpecial);
 
 		if (samples.length === 0 || samples[0].percentage < 10) {
@@ -57,7 +57,7 @@ class ProfileAnalysisWorker implements IRequestHandler, IProfileAnalysisWorker {
 				// ignore
 			}
 			if (!category) {
-				category = printCallFrame(loc.callFrame, false);
+				category = printCallFrameShort(loc.callFrame);
 			}
 			const value = aggegrateByCategory.get(category) ?? 0;
 			const newValue = value + node.selfTime;
@@ -76,11 +76,11 @@ function isSpecial(call: CdpCallFrame): boolean {
 	return call.functionName.startsWith('(') && call.functionName.endsWith(')');
 }
 
-function printCallFrame(frame: CdpCallFrame, fullPaths: boolean): string {
+function printCallFrameShort(frame: CdpCallFrame): string {
 	let result = frame.functionName || '(anonymous)';
 	if (frame.url) {
 		result += '#';
-		result += fullPaths ? frame.url : basename(frame.url);
+		result += basename(frame.url);
 		if (frame.lineNumber >= 0) {
 			result += ':';
 			result += frame.lineNumber + 1;
@@ -93,6 +93,24 @@ function printCallFrame(frame: CdpCallFrame, fullPaths: boolean): string {
 	return result;
 }
 
+function printCallFrameStackLike(frame: CdpCallFrame): string {
+	let result = frame.functionName || '(anonymous)';
+	if (frame.url) {
+		result += ' (';
+		result += frame.url;
+		if (frame.lineNumber >= 0) {
+			result += ':';
+			result += frame.lineNumber + 1;
+		}
+		if (frame.columnNumber >= 0) {
+			result += ':';
+			result += frame.columnNumber + 1;
+		}
+		result += ')';
+	}
+	return result;
+}
+
 function getHeaviestLocationIds(model: IProfileModel, topN: number) {
 	const stackSelfTime: { [locationId: number]: number } = {};
 	for (const node of model.nodes) {
@@ -107,7 +125,7 @@ function getHeaviestLocationIds(model: IProfileModel, topN: number) {
 	return new Set(locationIds);
 }
 
-function bottomUp(model: IProfileModel, topN: number, fullPaths: boolean = false) {
+function bottomUp(model: IProfileModel, topN: number) {
 	const root = BottomUpNode.root();
 	const locationIds = getHeaviestLocationIds(model, topN);
 
@@ -129,7 +147,8 @@ function bottomUp(model: IProfileModel, topN: number, fullPaths: boolean = false
 		const sample: BottomUpSample = {
 			selfTime: Math.round(node.selfTime / 1000),
 			totalTime: Math.round(node.aggregateTime / 1000),
-			location: printCallFrame(node.callFrame, fullPaths),
+			location: printCallFrameShort(node.callFrame),
+			absLocation: printCallFrameStackLike(node.callFrame),
 			url: node.callFrame.url,
 			caller: [],
 			percentage: Math.round(node.selfTime / (model.duration / 100)),
@@ -148,7 +167,11 @@ function bottomUp(model: IProfileModel, topN: number, fullPaths: boolean = false
 			}
 			if (top) {
 				const percentage = Math.round(top.selfTime / (node.selfTime / 100));
-				sample.caller.push({ percentage, location: printCallFrame(top.callFrame, false) });
+				sample.caller.push({
+					percentage,
+					location: printCallFrameShort(top.callFrame),
+					absLocation: printCallFrameStackLike(top.callFrame),
+				});
 				stack.push(top);
 			}
 		}

diff --git a/src/vs/platform/profiling/electron-sandbox/profileAnalysisWorkerService.ts b/src/vs/platform/profiling/electron-sandbox/profileAnalysisWorkerService.ts
@@ -30,7 +30,7 @@ export const IProfileAnalysisWorkerService = createDecorator<IProfileAnalysisWor
 
 export interface IProfileAnalysisWorkerService {
 	readonly _serviceBrand: undefined;
-	analyseBottomUp(profile: IV8Profile, callFrameClassifier: IScriptUrlClassifier, perfBaseline: number): Promise<ProfilingOutput>;
+	analyseBottomUp(profile: IV8Profile, callFrameClassifier: IScriptUrlClassifier, perfBaseline: number, sendAsErrorTelemtry: boolean): Promise<ProfilingOutput>;
 	analyseByLocation(profile: IV8Profile, locations: [location: URI, id: string][]): Promise<[category: string, aggregated: number][]>;
 }
 
@@ -64,7 +64,7 @@ class ProfileAnalysisWorkerService implements IProfileAnalysisWorkerService {
 		}
 	}
 
-	async analyseBottomUp(profile: IV8Profile, callFrameClassifier: IScriptUrlClassifier, perfBaseline: number): Promise<ProfilingOutput> {
+	async analyseBottomUp(profile: IV8Profile, callFrameClassifier: IScriptUrlClassifier, perfBaseline: number, sendAsErrorTelemtry: boolean): Promise<ProfilingOutput> {
 		return this._withWorker(async worker => {
 			const result = await worker.analyseBottomUp(profile);
 			if (result.kind === ProfilingOutput.Interesting) {
@@ -73,7 +73,7 @@ class ProfileAnalysisWorkerService implements IProfileAnalysisWorkerService {
 						sample,
 						perfBaseline,
 						source: callFrameClassifier(sample.url)
-					}, this._telemetryService, this._logService);
+					}, this._telemetryService, this._logService, sendAsErrorTelemtry);
 				}
 			}
 			return result.kind;

diff --git a/src/vs/workbench/contrib/extensions/electron-sandbox/extensionsAutoProfiler.ts b/src/vs/workbench/contrib/extensions/electron-sandbox/extensionsAutoProfiler.ts
@@ -139,7 +139,8 @@ export class ExtensionsAutoProfiler implements IWorkbenchContribution {
 			await this._profileAnalysisService.analyseBottomUp(
 				profile.data,
 				url => searchTree.findSubstr(URI.parse(url))?.identifier.value ?? '<<not-found>>',
-				this._perfBaseline
+				this._perfBaseline,
+				false
 			);
 		}
 

diff --git a/src/vs/workbench/contrib/performance/electron-sandbox/rendererAutoProfiler.ts b/src/vs/workbench/contrib/performance/electron-sandbox/rendererAutoProfiler.ts
@@ -76,7 +76,7 @@ export class RendererProfiling {
 
 					try {
 						const profile = await nativeHostService.profileRenderer(sessionId, 5000);
-						const output = await profileAnalysisService.analyseBottomUp(profile, _url => '<<renderer>>', perfBaseline);
+						const output = await profileAnalysisService.analyseBottomUp(profile, _url => '<<renderer>>', perfBaseline, true);
 						if (output === ProfilingOutput.Interesting) {
 							this._store(profile, sessionId);
 							break;