diff --git a/packages/utils/telemetry-utils/src/logger.ts b/packages/utils/telemetry-utils/src/logger.ts index 5abf73a0239f..de3443bba850 100644 --- a/packages/utils/telemetry-utils/src/logger.ts +++ b/packages/utils/telemetry-utils/src/logger.ts @@ -675,7 +675,11 @@ export class MultiSinkLogger extends TelemetryLogger { export interface IPerformanceEventMarkers { start?: true; end?: true; - cancel?: "generic" | "error"; // tells wether to issue "generic" or "error" category cancel event + cancel?: "generic" | "error"; // tells whether to issue "generic" or "error" category cancel event + /** + * If specified, _end events whose duration is greater than this threshold are logged as essential. + */ + endEventEssentialDurationThresholdMs?: number; } /** @@ -895,7 +899,36 @@ export class PerformanceEvent { event.duration = this.duration; } - this.logger.sendPerformanceEvent(event, error, this.logLevel); + this.logger.sendPerformanceEvent(event, error, this.getLogLevel(eventNameSuffix, event)); + } + + /** + * Get the LogLevel for performance events. + * @param eventNameSuffix - The suffix of the event name. + * @param event - The telemetry performance event. + * @returns The log level for the event. + * + */ + private getLogLevel( + eventNameSuffix: string, + event: ITelemetryPerformanceEventExt, + ): typeof LogLevel.verbose | typeof LogLevel.info | undefined { + if (eventNameSuffix === "cancel") { + // When undefined is returned, the LogLevel will be set to LogLevel.essential. See ChildLogger.send + return undefined; + } + + if ( + eventNameSuffix === "end" && + event.duration !== undefined && + this.markers.endEventEssentialDurationThresholdMs !== undefined && + event.duration > this.markers.endEventEssentialDurationThresholdMs + ) { + // When undefined is returned, the LogLevel will be set to LogLevel.essential. See ChildLogger.send + return undefined; + } + + return this.logLevel; } private static readonly eventHits = new Map(); diff --git a/packages/utils/telemetry-utils/src/test/performanceEvent.spec.ts b/packages/utils/telemetry-utils/src/test/performanceEvent.spec.ts index 8f3b11b5c9b6..b072a174383a 100644 --- a/packages/utils/telemetry-utils/src/test/performanceEvent.spec.ts +++ b/packages/utils/telemetry-utils/src/test/performanceEvent.spec.ts @@ -5,7 +5,8 @@ import { strict as assert } from "node:assert"; -import type { ITelemetryBaseEvent } from "@fluidframework/core-interfaces"; +import { LogLevel, type ITelemetryBaseEvent } from "@fluidframework/core-interfaces"; +import sinon from "sinon"; import { PerformanceEvent, TelemetryLogger } from "../logger.js"; import type { TelemetryLoggerExt } from "../telemetryTypes.js"; @@ -13,17 +14,21 @@ import type { TelemetryLoggerExt } from "../telemetryTypes.js"; class MockLogger extends TelemetryLogger implements TelemetryLoggerExt { public errorsLogged: number = 0; public eventsLogged: number = 0; + public readonly events: ITelemetryBaseEvent[] = []; + public readonly logLevels: (LogLevel | undefined)[] = []; public constructor() { super(); } - public send(event: ITelemetryBaseEvent): void { + public send(event: ITelemetryBaseEvent, logLevel?: LogLevel): void { if (event.category === "error") { ++this.errorsLogged; } ++this.eventsLogged; + this.events.push(event); + this.logLevels.push(logLevel); } } @@ -95,6 +100,85 @@ describe("PerformanceEvent", () => { ); }); + describe("Log level escalation", () => { + it("Logs below-threshold end events at the configured log level", () => { + const perfEvent = PerformanceEvent.start( + logger, + { eventName: "BelowThreshold" }, + { + end: true, + endEventEssentialDurationThresholdMs: Number.MAX_SAFE_INTEGER, + }, + true, + LogLevel.info, + ); + + perfEvent.end(); + + assert.deepStrictEqual(logger.logLevels, [LogLevel.info]); + assert.equal(logger.events[0]?.eventName, "BelowThreshold_end"); + }); + + it("Logs above-threshold end events as essential", () => { + const clock = sinon.useFakeTimers(); + try { + const perfEvent = PerformanceEvent.start( + logger, + { eventName: "AboveThreshold" }, + { + end: true, + endEventEssentialDurationThresholdMs: 0, + }, + true, + LogLevel.info, + ); + + clock.tick(1); + perfEvent.end(); + + assert.deepStrictEqual(logger.logLevels, [LogLevel.essential]); + assert.equal(logger.events[0]?.eventName, "AboveThreshold_end"); + } finally { + clock.restore(); + } + }); + + it("Logs cancel events as essential by default", () => { + const perfEvent = PerformanceEvent.start( + logger, + { eventName: "EssentialCancel" }, + undefined, + true, + LogLevel.info, + ); + + perfEvent.cancel(); + + assert.deepStrictEqual(logger.logLevels, [LogLevel.essential]); + assert.equal(logger.events[0]?.eventName, "EssentialCancel_cancel"); + assert.equal(logger.events[0]?.category, "generic"); + }); + + it("Continues to log error-category performance events as essential", () => { + const perfEvent = PerformanceEvent.start( + logger, + { eventName: "ErrorCategory", category: "error" }, + { + end: true, + endEventEssentialDurationThresholdMs: Number.MAX_SAFE_INTEGER, + }, + true, + LogLevel.info, + ); + + perfEvent.end(); + + assert.deepStrictEqual(logger.logLevels, [LogLevel.essential]); + assert.equal(logger.events[0]?.eventName, "ErrorCategory_end"); + assert.equal(logger.events[0]?.category, "error"); + }); + }); + describe("Event sampling", () => { it("Events are logged at least once", async () => { await PerformanceEvent.timedExecAsync(