From 8fd4230965e3a630e68fdae949c187fc9f7b9b7b Mon Sep 17 00:00:00 2001 From: Johannes Date: Mon, 23 Jan 2023 17:01:17 +0100 Subject: [PATCH] send auto profiling stack traces also as error telemetry https://github.com/microsoft/vscode/issues/170954 --- .../profiling/common/profilingModel.ts | 3 +- .../common/profilingTelemetrySpec.ts | 29 +++++++++++---- .../electron-sandbox/profileAnalysisWorker.ts | 37 +++++++++++++++---- .../profileAnalysisWorkerService.ts | 6 +-- .../extensionsAutoProfiler.ts | 3 +- .../electron-sandbox/rendererAutoProfiler.ts | 2 +- 6 files changed, 60 insertions(+), 20 deletions(-) diff --git a/src/vs/platform/profiling/common/profilingModel.ts b/src/vs/platform/profiling/common/profilingModel.ts index a5ab71cf071c5..82202203388d3 100644 --- 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 index 14b53bd6c1109..2fa784bbc0406 100644 --- 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(`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 index af25e4c2244fa..0d1ac1c4a655e 100644 --- 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 index 65d778edad94d..ad6a25cd679b9 100644 --- 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; + analyseBottomUp(profile: IV8Profile, callFrameClassifier: IScriptUrlClassifier, perfBaseline: number, sendAsErrorTelemtry: boolean): Promise; 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 { + async analyseBottomUp(profile: IV8Profile, callFrameClassifier: IScriptUrlClassifier, perfBaseline: number, sendAsErrorTelemtry: boolean): Promise { 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 index 554cc3fc208a7..c496cbcc342c6 100644 --- 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 ?? '<>', - 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 index 85120e038274d..2efc0ec8e662e 100644 --- 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 => '<>', perfBaseline); + const output = await profileAnalysisService.analyseBottomUp(profile, _url => '<>', perfBaseline, true); if (output === ProfilingOutput.Interesting) { this._store(profile, sessionId); break;