Skip to content
Merged
Show file tree
Hide file tree
Changes from 1 commit
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
32 changes: 30 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,15 @@ 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;
/**
* If specified, _cancel events are logged as essential while preserving the configured cancel category.
*/
logCancelAsEssential?: true;
}

/**
Expand Down Expand Up @@ -895,7 +903,27 @@ export class PerformanceEvent {
event.duration = this.duration;
}

this.logger.sendPerformanceEvent(event, error, this.logLevel);
this.logger.sendPerformanceEvent(event, error, this.getLogLevel(eventNameSuffix, event));
}

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" && this.markers.logCancelAsEssential === true) {
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
106 changes: 104 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,29 @@

import { strict as assert } from "node:assert";

import type { ITelemetryBaseEvent } from "@fluidframework/core-interfaces";
import { LogLevel, type ITelemetryBaseEvent } from "@fluidframework/core-interfaces";

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 All @@ -34,6 +38,10 @@ describe("PerformanceEvent", () => {
const callback = (): void => {
callbackCalls++;
};
const delay = async (): Promise<void> =>
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.

See if you can quickly switch to using Sinon fake timers, which lets you test the delay without taking any real time. Hopefully you can one-shot it with Copilot.

These little ms setTimeouts can quickly add up and unnecessarily bloat unit test run times.

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.

Admittedly 1ms is probably not make-or-break but still good practice to avoid real delays. More reliable way to test too

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.

Applied change

new Promise<void>((resolve) => {
setTimeout(resolve, 1);
});
const asyncCallback = async (event: PerformanceEvent): Promise<string | void> => {
const outerPromise = new Promise<string>((resolve, reject) => {
Promise.resolve("A")
Expand Down Expand Up @@ -95,6 +103,100 @@ 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", async () => {
const perfEvent = PerformanceEvent.start(
logger,
{ eventName: "AboveThreshold" },
{
end: true,
endEventEssentialDurationThresholdMs: 0,
},
true,
LogLevel.info,
);

await delay();
perfEvent.end();

assert.deepStrictEqual(logger.logLevels, [LogLevel.essential]);
assert.equal(logger.events[0]?.eventName, "AboveThreshold_end");
});

it("Logs cancel events as essential when configured", () => {
const perfEvent = PerformanceEvent.start(
logger,
{ eventName: "EssentialCancel" },
{
cancel: "generic",
logCancelAsEssential: true,
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.

Can we make this the default? Feels likely we'll always want this

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.

I assumed that when you made this the default, I'm guessing you were referring to the logCancelAsEssential code. That change was made

},
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("Preserves scalar LogLevel.info behavior when marker escalation is not configured", () => {
const perfEvent = PerformanceEvent.start(
logger,
{ eventName: "InfoCancel" },
{
cancel: "generic",
},
true,
LogLevel.info,
);

perfEvent.cancel();

assert.deepStrictEqual(logger.logLevels, [LogLevel.info]);
assert.equal(logger.events[0]?.eventName, "InfoCancel_cancel");
});

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