diff --git a/src/chrome/chromeDebugAdapter.ts b/src/chrome/chromeDebugAdapter.ts index fcd607c64..f2d61af30 100644 --- a/src/chrome/chromeDebugAdapter.ts +++ b/src/chrome/chromeDebugAdapter.ts @@ -21,7 +21,7 @@ import {StoppedEvent2, ReasonType} from './stoppedEvent'; import * as errors from '../errors'; import * as utils from '../utils'; -import {telemetry} from '../telemetry'; +import {telemetry, BatchTelemetryReporter, IExecutionResultTelemetryProperties} from '../telemetry'; import {LineColTransformer} from '../transformers/lineNumberTransformer'; import {BasePathTransformer} from '../transformers/basePathTransformer'; @@ -140,8 +140,11 @@ export abstract class ChromeDebugAdapter implements IDebugAdapter { // won't be send before the corresponding 'new' event has been sent private _sourceLoadedQueue: Promise = Promise.resolve(null); + private _batchTelemetryReporter: BatchTelemetryReporter; + public constructor({ chromeConnection, lineColTransformer, sourceMapTransformer, pathTransformer, targetFilter, enableSourceMapCaching }: IChromeDebugAdapterOpts, session: ChromeDebugSession) { telemetry.setupEventHandler(e => session.sendEvent(e)); + this._batchTelemetryReporter = new BatchTelemetryReporter(telemetry); this._session = session; this._chromeConnection = new (chromeConnection || ChromeConnection)(undefined, targetFilter); @@ -329,6 +332,7 @@ export abstract class ChromeDebugAdapter implements IDebugAdapter { } public shutdown(): void { + this._batchTelemetryReporter.finalize(); this._inShutdown = true; this._session.shutdown(); } @@ -363,7 +367,11 @@ export abstract class ChromeDebugAdapter implements IDebugAdapter { * Hook up all connection events */ protected hookConnectionEvents(): void { - this.chrome.Debugger.onPaused(params => this.onPaused(params)); + this.chrome.Debugger.onPaused((params) => { + this.runAndMeasureProcessingTime('crdp/notification/onPaused', () => { + return this.onPaused(params); + }); + }); this.chrome.Debugger.onResumed(() => this.onResumed()); this.chrome.Debugger.onScriptParsed(params => this.onScriptParsed(params)); this.chrome.Debugger.onBreakpointResolved(params => this.onBreakpointResolved(params)); @@ -376,6 +384,27 @@ export abstract class ChromeDebugAdapter implements IDebugAdapter { this._chromeConnection.onClose(() => this.terminateSession('websocket closed')); } + private async runAndMeasureProcessingTime(notificationName: string, procedure: () => Promise): Promise { + const startTime = Date.now(); + const startTimeMark = process.hrtime(); + let properties: IExecutionResultTelemetryProperties = { + startTime: startTime.toString() + }; + + try { + await procedure(); + properties.successful = 'true'; + } catch (e) { + properties.successful = 'false'; + properties.exceptionType = 'firstChance'; + utils.fillErrorDetails(properties, e); + } + + const elapsedTime = utils.calculateElapsedTime(startTimeMark); + properties.timeTakenInMilliseconds = elapsedTime.toString(); + this._batchTelemetryReporter.reportEvent(notificationName, properties); + } + /** * Enable clients and run connection */ diff --git a/src/chrome/chromeDebugSession.ts b/src/chrome/chromeDebugSession.ts index 2a95e2be4..d69c16213 100644 --- a/src/chrome/chromeDebugSession.ts +++ b/src/chrome/chromeDebugSession.ts @@ -13,7 +13,8 @@ import {BaseSourceMapTransformer} from '../transformers/baseSourceMapTransformer import {LineColTransformer} from '../transformers/lineNumberTransformer'; import {IDebugAdapter} from '../debugAdapterInterfaces'; -import { telemetry } from '../telemetry'; +import { telemetry, ExceptionType, IExecutionResultTelemetryProperties } from '../telemetry'; +import * as utils from '../utils'; export interface IChromeDebugAdapterOpts { targetFilter?: ITargetFilter; @@ -33,19 +34,6 @@ export interface IChromeDebugSessionOpts extends IChromeDebugAdapterOpts { extensionName: string; } -export type ExceptionType = "uncaughtException" | "unhandledRejection" | "generic"; - -export interface IExceptionTelemetryProperties { - // There is an issue on some clients and reportEvent only currently accept strings properties, - // hence all the following properties must be strings. - successful?: "true" | "false"; - exceptionType?: ExceptionType; - exceptionMessage?: string; - exceptionName?: string; - exceptionStack?: string; - timeTakenInMilliseconds?: string; -} - export const ErrorTelemetryEventName = 'error'; // A failed request can return either an Error, an error from Chrome, or a DebugProtocol.Message which is returned as-is to the client @@ -98,12 +86,12 @@ export class ChromeDebugSession extends LoggingDebugSession { }; const reportErrorTelemetry = (err, exceptionType: ExceptionType) => { - let properties: IExceptionTelemetryProperties = {}; + let properties: IExecutionResultTelemetryProperties = {}; properties.successful = "false"; properties.exceptionType = exceptionType; properties.timeTakenInMilliseconds = ""; - this.fillErrorDetails(properties, err); + utils.fillErrorDetails(properties, err); telemetry.reportEvent(ErrorTelemetryEventName, properties); }; @@ -151,26 +139,20 @@ export class ChromeDebugSession extends LoggingDebugSession { // { command: request.command, type: request.type }; private async reportTelemetry(eventName: string, propertiesSpecificToAction: {[property: string]: string}, action: (reportFailure: (failure: any) => void) => Promise): Promise { const startProcessingTime = process.hrtime(); - const properties: IExceptionTelemetryProperties = propertiesSpecificToAction; + const properties: IExecutionResultTelemetryProperties = propertiesSpecificToAction; let failed = false; const sendTelemetry = () => { - const NanoSecondsPerMillisecond = 1000000; - const MillisecondsPerSecond = 1000; - - const ellapsedTime = process.hrtime(startProcessingTime); - const ellapsedMilliseconds = ellapsedTime[0] * MillisecondsPerSecond + ellapsedTime[1] / NanoSecondsPerMillisecond; - properties.timeTakenInMilliseconds = ellapsedMilliseconds.toString(); - + properties.timeTakenInMilliseconds = utils.calculateElapsedTime(startProcessingTime).toString(); telemetry.reportEvent(eventName, properties); }; const reportFailure = e => { failed = true; properties.successful = "false"; - properties.exceptionType = "generic"; - this.fillErrorDetails(properties, e); + properties.exceptionType = "firstChance"; + utils.fillErrorDetails(properties, e); sendTelemetry(); }; @@ -221,16 +203,6 @@ export class ChromeDebugSession extends LoggingDebugSession { private sendUnknownCommandResponse(response: DebugProtocol.Response, command: string): void { this.sendErrorResponse(response, 1014, `[${this._extensionName}] Unrecognized request: ${command}`, null, ErrorDestination.Telemetry); } - - private fillErrorDetails(properties: IExceptionTelemetryProperties, e: any): void { - properties.exceptionMessage = e.message || e.toString(); - if (e.name) { - properties.exceptionName = e.name; - } - if (e.stack) { - properties.exceptionStack = e.stack; - } - } } function logVersionInfo(): void { diff --git a/src/telemetry.ts b/src/telemetry.ts index 78ee3fe76..3369ff75f 100644 --- a/src/telemetry.ts +++ b/src/telemetry.ts @@ -5,6 +5,19 @@ import {DebugProtocol} from 'vscode-debugprotocol'; import {OutputEvent} from 'vscode-debugadapter'; +export type ExceptionType = "uncaughtException" | "unhandledRejection" | "firstChance"; +export interface IExecutionResultTelemetryProperties { + // There is an issue on some clients and reportEvent only currently accept strings properties, + // hence all the following properties must be strings. + successful?: "true" | "false"; + exceptionType?: ExceptionType; + exceptionMessage?: string; + exceptionName?: string; + exceptionStack?: string; + startTime?: string; + timeTakenInMilliseconds?: string; +} + export interface ITelemetryReporter { reportEvent(name: string, data?: any): void; setupEventHandler(_sendEvent: (event: DebugProtocol.Event) => void): void; @@ -36,4 +49,118 @@ export class NullTelemetryReporter implements ITelemetryReporter { } +export const DefaultTelemetryIntervalInMilliseconds = 10000; + +export class BatchTelemetryReporter { + private _eventBuckets: {[eventName: string]: any}; + private _timer: NodeJS.Timer; + + public constructor(private _telemetryReporter: TelemetryReporter, private _cadenceInMilliseconds: number = DefaultTelemetryIntervalInMilliseconds) { + this.reset(); + this.setup(); + } + + public reportEvent(name: string, data?: any): void { + if (!this._eventBuckets[name]) { + this._eventBuckets[name] = []; + } + + this._eventBuckets[name].push(data); + } + + public finalize(): void { + this.send(); + clearInterval(this._timer); + } + + private setup(): void { + this._timer = setInterval(() => this.send(), this._cadenceInMilliseconds); + } + + private reset(): void { + this._eventBuckets = {}; + } + + private send(): void { + for (const eventName in this._eventBuckets) { + const bucket = this._eventBuckets[eventName]; + let properties = BatchTelemetryReporter.transfromBucketData(bucket); + this._telemetryReporter.reportEvent(eventName, properties); + } + + this.reset(); + } + /** + * Transfrom the bucket of events data from the form: + * [{ + * p1: v1, + * p2: v2 + * }, + * { + * p1: w1, + * p2: w2 + * p3: w3 + * }] + * + * to + * { + * p1: [v1, w1], + * p2: [v2, w2], + * p3: [null, w3] + * } + * + * + * The later form is easier for downstream telemetry analysis. + */ + private static transfromBucketData(bucket: any[]): {[groupedPropertyValue: string]: string} { + const allPropertyNamesInTheBucket = BatchTelemetryReporter.collectPropertyNamesFromAllEvents(bucket); + let properties = {}; + + // Run through all the entries, create a holder for all potential property names + for (const key of allPropertyNamesInTheBucket) { + properties[`aggregated.${key}`] = []; + } + + // Run through again, collect the values for each property name. + for (const entry of bucket) { + for (const key of allPropertyNamesInTheBucket) { + properties[`aggregated.${key}`].push(entry[key] == undefined? null: entry[key]); + } + } + + // Serialize each array as the final aggregated property value. + for (const key of allPropertyNamesInTheBucket) { + properties[`aggregated.${key}`] = JSON.stringify(properties[`aggregated.${key}`]); + } + + return properties; + } + + /** + * Get the property keys from all the entries of a event bucket: + * + * So + * [{ + * p1: v1, + * p2: v2 + * }, + * { + * p1: w1, + * p2: w2 + * p3: w3 + * }] + * + * will return ['p1', 'p2', 'p3'] + */ + private static collectPropertyNamesFromAllEvents(bucket: any[]): string[] { + let propertyNamesSet = {}; + for (const entry of bucket) { + for (const key of Object.keys(entry)) { + propertyNamesSet[key] = true; + } + } + return Object.keys(propertyNamesSet); + } +} + export const telemetry = new TelemetryReporter(); \ No newline at end of file diff --git a/src/utils.ts b/src/utils.ts index 289497ec5..f3caae3fe 100644 --- a/src/utils.ts +++ b/src/utils.ts @@ -11,6 +11,8 @@ import {Handles, logger} from 'vscode-debugadapter'; import * as http from 'http'; import * as https from 'https'; +import {IExecutionResultTelemetryProperties} from './telemetry'; + export const enum Platform { Windows, OSX, Linux } @@ -549,4 +551,25 @@ export function isNumber(num: number): boolean { export function toVoidP(p: Promise): Promise { return p.then(() => { }); +} + +export type HighResTimer = [number, number]; + +export function calculateElapsedTime(startProcessingTime: HighResTimer): number { + const NanoSecondsPerMillisecond = 1000000; + const NanoSecondsPerSecond = 1e9; + + const ellapsedTime = process.hrtime(startProcessingTime); + const ellapsedMilliseconds = (ellapsedTime[0] * NanoSecondsPerSecond + ellapsedTime[1]) / NanoSecondsPerMillisecond; + return ellapsedMilliseconds; +} + +export function fillErrorDetails(properties: IExecutionResultTelemetryProperties, e: any): void { + properties.exceptionMessage = e.message || e.toString(); + if (e.name) { + properties.exceptionName = e.name; + } + if (e.stack) { + properties.exceptionStack = e.stack; + } } \ No newline at end of file