Skip to content
Merged
Show file tree
Hide file tree
Changes from 6 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
36 changes: 34 additions & 2 deletions packages/utils/telemetry-utils/src/logger.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}

/**
Expand Down Expand Up @@ -895,7 +899,35 @@ 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.
*
* If undefined is returned then the LogLevel will be set as essential. See {@link ChildLogger.send}
*/
private getLogLevel(
eventNameSuffix: string,
event: ITelemetryPerformanceEventExt,
): typeof LogLevel.verbose | typeof LogLevel.info | undefined {
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why are we using undefined to signal essential? Seems like unnecessarily tight coupling with the default specified elsewhere

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

because the sendPerformanceEvent can only receive LogLevel.info, LogLevel.verbose or undefined. So we need it to send undefined so that it defaults to LogLevel.essential

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh ok. Might be clearer to update that to take essential at some point

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So the reason why I made it that way is because sendPerformanceEvent can only take LogLevel.verbose, LogLevel.info or undefined. With the breaking change happening in #26910, that should be fixable and then it can take esential.

if (eventNameSuffix === "cancel") {
return undefined;
Comment thread
markfields marked this conversation as resolved.
}

if (
eventNameSuffix === "end" &&
event.duration !== undefined &&
this.markers.endEventEssentialDurationThresholdMs !== undefined &&
event.duration > this.markers.endEventEssentialDurationThresholdMs
) {
return undefined;
}

return this.logLevel;
}

private static readonly eventHits = new Map<string, number>();
Expand Down
88 changes: 86 additions & 2 deletions packages/utils/telemetry-utils/src/test/performanceEvent.spec.ts
Original file line number Diff line number Diff line change
Expand Up @@ -5,25 +5,30 @@

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

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

Expand Down Expand Up @@ -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(
Expand Down
Loading