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

https://github.com/microsoft/vscode/issues/170954
This commit is contained in:
Johannes Rieken 2023-01-23 17:16:16 +01:00 committed by GitHub
parent b87234ddca
commit 2b5c4dd220
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
6 changed files with 60 additions and 20 deletions

View file

@ -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;
}

View file

@ -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 ')}`;
}
}

View file

@ -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);
}
}

View file

@ -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;

View file

@ -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
);
}

View file

@ -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;