From 2ea3c8294fe7fc64de3c1b49cc82b036e26ba612 Mon Sep 17 00:00:00 2001 From: Johannes Rieken Date: Fri, 21 Oct 2022 20:12:39 +0200 Subject: [PATCH] auto profiling telemetry tweak (#164259) * auto profiling telemetry tweak reuse the same code to send the telemetry data for the renderer and the extension host send telemetry event without annotated stacktraces send fake error event with annotated stacktraces * use fixed telemetry name and source to tell events apart, drop error log and send callers twice (annotated and not) * piggy bag on the experiemental profiling setting and control extension host profile analysis by that --- .../common/profilingTelemetrySpec.ts | 50 ++++++++++++++++--- .../electron-main/windowProfiling.ts | 24 +++------ .../extensionsAutoProfiler.ts | 26 +++++----- 3 files changed, 60 insertions(+), 40 deletions(-) diff --git a/src/vs/platform/profiling/common/profilingTelemetrySpec.ts b/src/vs/platform/profiling/common/profilingTelemetrySpec.ts index cb0ab79a0e9..14b53bd6c11 100644 --- a/src/vs/platform/profiling/common/profilingTelemetrySpec.ts +++ b/src/vs/platform/profiling/common/profilingTelemetrySpec.ts @@ -3,26 +3,60 @@ * Licensed under the MIT License. See License.txt in the project root for license information. *--------------------------------------------------------------------------------------------*/ -export type TelemetrySampleData = { - sessionId: string; +import { ILogService } from 'vs/platform/log/common/log'; +import { BottomUpSample } from 'vs/platform/profiling/common/profilingModel'; +import { ITelemetryService } from 'vs/platform/telemetry/common/telemetry'; + +type TelemetrySampleData = { selfTime: number; totalTime: number; percentage: number; perfBaseline: number; functionName: string; - callstack: string; - extensionId: string; + callers: string; + callersAnnotated: string; + source: string; }; -export type TelemetrySampleDataClassification = { +type TelemetrySampleDataClassification = { owner: 'jrieken'; comment: 'A callstack that took a long time to execute'; - sessionId: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'Session identifier that allows to correlate samples from one profile' }; selfTime: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Self time of the sample' }; totalTime: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Total time of the sample' }; percentage: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Relative time (percentage) of the sample' }; perfBaseline: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; isMeasurement: true; comment: 'Performance baseline for the machine' }; functionName: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'The name of the sample' }; - callstack: { classification: 'CallstackOrException'; purpose: 'PerformanceAndHealth'; comment: 'The stacktrace leading into the sample' }; - extensionId: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'The extension for the sample (iff applicable)' }; + callers: { classification: 'CallstackOrException'; purpose: 'PerformanceAndHealth'; comment: 'The heaviest call trace into this sample' }; + callersAnnotated: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'The heaviest call trace into this sample annotated with respective costs' }; + source: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'The source - either renderer or an extension' }; }; + +export interface SampleData { + perfBaseline: number; + sample: BottomUpSample; + source: string; +} + +export function reportSample(data: SampleData, telemetryService: ITelemetryService, logService: ILogService): 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, + selfTime: sample.selfTime, + totalTime: sample.totalTime, + percentage: sample.percentage, + functionName: sample.location, + callers: sample.caller.map(c => c.location).join('<'), + callersAnnotated: sample.caller.map(c => `${c.percentage}|${c.location}`).join('<'), + source + }); + +} diff --git a/src/vs/platform/profiling/electron-main/windowProfiling.ts b/src/vs/platform/profiling/electron-main/windowProfiling.ts index 762d8305cc5..610b8d7e474 100644 --- a/src/vs/platform/profiling/electron-main/windowProfiling.ts +++ b/src/vs/platform/profiling/electron-main/windowProfiling.ts @@ -13,7 +13,7 @@ import { join } from 'vs/base/common/path'; import { ITelemetryService } from 'vs/platform/telemetry/common/telemetry'; import { Utils } from 'vs/platform/profiling/common/profiling'; import { bottomUp, buildModel, } from 'vs/platform/profiling/common/profilingModel'; -import { TelemetrySampleData, TelemetrySampleDataClassification } from 'vs/platform/profiling/common/profilingTelemetrySpec'; +import { reportSample } from 'vs/platform/profiling/common/profilingTelemetrySpec'; import { onUnexpectedError } from 'vs/base/common/errors'; export const enum ProfilingOutput { @@ -92,23 +92,11 @@ export class WindowProfiler { // send telemetry events for (const sample of samples) { - const data: TelemetrySampleData = { - sessionId: this._sessionId, - perfBaseline, - selfTime: sample.selfTime, - totalTime: sample.totalTime, - percentage: sample.percentage, - functionName: sample.location, - callstack: sample.caller.map(c => c.location).join('<'), - extensionId: '<>' - }; - this._telemetryService.publicLog2('prof.freeze.sample', data); - - // log a fake error with a clearer stack - const fakeError = new Error(); - fakeError.name = 'PerfHeavyFunction'; - fakeError.stack = `Spend ${sample.selfTime}ms in ${sample.location}\n` + sample.caller.map(c => `\t at ${c.location} (${c.percentage}%)`).join('\n'); - this._logService.error(fakeError, `[perf] HEAVY function sample`); + reportSample( + { sample, perfBaseline, source: '<>' }, + this._telemetryService, + this._logService + ); } // save to disk diff --git a/src/vs/workbench/contrib/extensions/electron-sandbox/extensionsAutoProfiler.ts b/src/vs/workbench/contrib/extensions/electron-sandbox/extensionsAutoProfiler.ts index 6bbf5683cf4..111d485e358 100644 --- a/src/vs/workbench/contrib/extensions/electron-sandbox/extensionsAutoProfiler.ts +++ b/src/vs/workbench/contrib/extensions/electron-sandbox/extensionsAutoProfiler.ts @@ -28,9 +28,10 @@ import { bottomUp, buildModel } from 'vs/platform/profiling/common/profilingMode import { TernarySearchTree } from 'vs/base/common/ternarySearchTree'; import { Schemas } from 'vs/base/common/network'; import { URI } from 'vs/base/common/uri'; -import { TelemetrySampleData, TelemetrySampleDataClassification } from 'vs/platform/profiling/common/profilingTelemetrySpec'; +import { reportSample } from 'vs/platform/profiling/common/profilingTelemetrySpec'; import { generateUuid } from 'vs/base/common/uuid'; import { ITimerService } from 'vs/workbench/services/timer/browser/timerService'; +import { IConfigurationService } from 'vs/platform/configuration/common/configuration'; export class ExtensionsAutoProfiler implements IWorkbenchContribution { @@ -49,6 +50,7 @@ export class ExtensionsAutoProfiler implements IWorkbenchContribution { @IEditorService private readonly _editorService: IEditorService, @IInstantiationService private readonly _instantiationService: IInstantiationService, @INativeWorkbenchEnvironmentService private readonly _environmentServie: INativeWorkbenchEnvironmentService, + @IConfigurationService private readonly _configService: IConfigurationService, @IFileService private readonly _fileService: IFileService, @ITimerService timerService: ITimerService ) { @@ -201,19 +203,15 @@ export class ExtensionsAutoProfiler implements IWorkbenchContribution { }); // send heavy samples - const samples = bottomUp(model, 5, false); - for (const sample of samples) { - const data: TelemetrySampleData = { - sessionId, - selfTime: sample.selfTime, - totalTime: sample.totalTime, - percentage: sample.percentage, - functionName: sample.location, - callstack: sample.caller.map(c => `${c.percentage}|${c.location}`).join('<'), - extensionId: searchTree.findSubstr(URI.parse(sample.url))?.identifier.value ?? '', - perfBaseline: this._perfBaseline, - }; - this._telemetryService.publicLog2('exthostunresponsive.sample', data); + if (this._configService.getValue('application.experimental.rendererProfiling')) { + const samples = bottomUp(model, 5, false); + for (const sample of samples) { + reportSample( + { sample, perfBaseline: this._perfBaseline, source: searchTree.findSubstr(URI.parse(sample.url))?.identifier.value ?? '<>' }, + this._telemetryService, + this._logService + ); + } } // add to running extensions view