Track summarizer current step for timeout telemetry

packages/runtime/container-runtime/src/containerRuntime.ts

@@ -3931,6 +3931,10 @@ export class ContainerRuntime
 		 * True to run GC sweep phase after the mark phase
 		 */
 		runSweep?: boolean;
+		/**
+		 * Telemetry context to populate during summarization.
+		 */
+		telemetryContext?: TelemetryContext;
 	}): Promise<ISummaryTreeWithStats> {
 		this.verifyNotClosed();
 
@@ -3941,9 +3945,10 @@ export class ContainerRuntime
 			runGC = this.garbageCollector.shouldRunGC,
 			runSweep,
 			fullGC,
+			telemetryContext: providedTelemetryContext,
 		} = options;
 
-		const telemetryContext = new TelemetryContext();
+		const telemetryContext = providedTelemetryContext ?? new TelemetryContext();
 		// Add the options that are used to generate this summary to the telemetry context.
 		telemetryContext.setMultiple("fluid_Summarize", "Options", {
 			fullTree,
@@ -4185,6 +4190,7 @@ export class ContainerRuntime
 			summaryLogger,
 			latestSummaryRefSeqNum,
 		} = options;
+		const telemetryContext = options.telemetryContext ?? new TelemetryContext();
 		// The summary number for this summary. This will be updated during the summary process, so get it now and
 		// use it for all events logged during this summary.
 		const summaryNumber = this.nextSummaryNumber;
@@ -4372,6 +4378,7 @@ export class ContainerRuntime
 					trackState: true,
 					summaryLogger: summaryNumberLogger,
 					runGC: this.garbageCollector.shouldRunGC,
+					telemetryContext,
 				});
 			} catch (error) {
 				return {

packages/runtime/container-runtime/src/summary/summarizerTypes.ts

@@ -26,6 +26,7 @@ import type {
 	ITelemetryLoggerExt,
 	ITelemetryLoggerPropertyBag,
 } from "@fluidframework/telemetry-utils/internal";
+import type { TelemetryContext } from "@fluidframework/runtime-utils/internal";
 
 import type { SummarizeReason } from "./summarizerUtils.js";
 import type {
@@ -167,6 +168,10 @@ export interface ISubmitSummaryOptions extends ISummarizeOptions {
 	 * The sequence number of the latest summary used to validate if summary state is correct before summarizing
 	 */
 	readonly latestSummaryRefSeqNum: number;
+	/**
+	 * Shared telemetry context for the current summarize attempt.
+	 */
+	telemetryContext?: TelemetryContext;
 }
 
 /**

packages/runtime/container-runtime/src/summary/summaryDelayLoadedModule/summaryGenerator.ts

@@ -12,6 +12,7 @@ import {
 	PerformanceEvent,
 	wrapError,
 } from "@fluidframework/telemetry-utils/internal";
+import { TelemetryContext } from "@fluidframework/runtime-utils/internal";
 
 import type {
 	IRefreshSummaryAckOptions,
@@ -42,6 +43,7 @@ const maxSummarizeTimeoutCount = 5; // Double and resend 5 times
  */
 export class SummaryGenerator {
 	private readonly summarizeTimer: Timer;
+	private activeTelemetryContext?: TelemetryContext;
 	constructor(
 		private readonly pendingAckTimer: IPromiseTimer,
 		private readonly heuristicData: ISummarizeHeuristicData,
@@ -85,7 +87,16 @@ export class SummaryGenerator {
 		submitSummaryOptions: ISubmitSummaryOptions,
 		resultsBuilder: SummarizeResultBuilder,
 	): Promise<void> {
-		const { summaryLogger, cancellationToken, ...summarizeOptions } = submitSummaryOptions;
+		const {
+			summaryLogger,
+			cancellationToken,
+			telemetryContext = new TelemetryContext(),
+			...summarizeOptions
+		} = submitSummaryOptions;
+
+		telemetryContext.currentSummarizeStep = "submitSummary";
+		const submitOptions = { ...submitSummaryOptions, telemetryContext };
+		this.activeTelemetryContext = telemetryContext;
 
 		// Note: timeSinceLastAttempt and timeSinceLastSummary for the
 		// first summary are basically the time since the summarizer was loaded.
@@ -148,10 +159,12 @@ export class SummaryGenerator {
 		// Wait to generate and send summary
 		this.summarizeTimer.start();
 		try {
+			telemetryContext.currentSummarizeStep = "generateSummary";
 			// Need to save refSeqNum before we record new attempt (happens as part of submitSummaryCallback)
 			const lastAttemptRefSeqNum = this.heuristicData.lastAttempt.refSequenceNumber;
 
-			summaryData = await this.submitSummaryCallback(submitSummaryOptions);
+			summaryData = await this.submitSummaryCallback(submitOptions);
+			telemetryContext.currentSummarizeStep = "submitSummaryOp";
 
 			// Cumulatively add telemetry properties based on how far generateSummary went.
 			const referenceSequenceNumber = summaryData.referenceSequenceNumber;
@@ -189,6 +202,7 @@ export class SummaryGenerator {
 			 * exceed the number of ops since last summary + number of data store whose reference state changed.
 			 */
 			if (submitSummaryOptions.fullTree !== true) {
+				telemetryContext.currentSummarizeStep = "watchSummary";
 				const { summarizedDataStoreCount, gcStateUpdatedDataStoreCount = 0 } =
 					summaryData.summaryStats;
 				if (
@@ -227,6 +241,8 @@ export class SummaryGenerator {
 			this.summarizeTimer.clear();
 		}
 
+		telemetryContext.currentSummarizeStep = "waitForSummaryAck";
+
 		try {
 			const pendingTimeoutP = this.pendingAckTimer.start();
 			const summary = this.summaryWatcher.watchSummary(summaryData.clientSequenceNumber);
@@ -300,6 +316,7 @@ export class SummaryGenerator {
 				...summarizeTelemetryProps,
 			};
 			if (ackNackOp.type === MessageType.SummaryAck) {
+				telemetryContext.currentSummarizeStep = "ackReceived";
 				this.heuristicData.markLastAttemptAsSuccessful();
 				this.successfulSummaryCallback();
 				summarizeEvent.end({
@@ -324,6 +341,7 @@ export class SummaryGenerator {
 			} else {
 				// Check for retryDelay in summaryNack response.
 				assert(ackNackOp.type === MessageType.SummaryNack, 0x274 /* "type check" */);
+				telemetryContext.currentSummarizeStep = "nackReceived";
 				const summaryNack = ackNackOp.contents;
 				const errorMessage = summaryNack?.message;
 				const retryAfterSeconds = summaryNack?.retryAfter;
@@ -350,6 +368,7 @@ export class SummaryGenerator {
 			}
 		} finally {
 			this.pendingAckTimer.clear();
+			this.activeTelemetryContext = undefined;
 		}
 	}
 
@@ -408,6 +427,7 @@ export class SummaryGenerator {
 			eventName: "SummarizeTimeout",
 			timeoutTime: time,
 			timeoutCount: count,
+			currentSummarizeStep: this.activeTelemetryContext?.currentSummarizeStep,
 		});
 		if (count < maxSummarizeTimeoutCount) {
 			// Double and start a new timer
@@ -420,5 +440,6 @@ export class SummaryGenerator {
 
 	public dispose(): void {
 		this.summarizeTimer.clear();
+		this.activeTelemetryContext = undefined;
 	}
 }

packages/runtime/datastore/api-report/datastore.legacy.beta.api.md

@@ -131,7 +131,7 @@ export interface ISharedObjectRegistry {
 export const mixinRequestHandler: (requestHandler: (request: IRequest, runtime: FluidDataStoreRuntime) => Promise<IResponse>, Base?: typeof FluidDataStoreRuntime) => typeof FluidDataStoreRuntime;
 
 // @beta @legacy
-export const mixinSummaryHandler: (handler: (runtime: FluidDataStoreRuntime) => Promise<{
+export const mixinSummaryHandler: (handler: (runtime: FluidDataStoreRuntime, setCurrentSummarizeStep: (currentStep: string) => void) => Promise<{
     path: string[];
     content: string;
 } | undefined>, Base?: typeof FluidDataStoreRuntime) => typeof FluidDataStoreRuntime;

packages/runtime/datastore/src/dataStoreRuntime.ts

@@ -65,6 +65,8 @@ import {
 	type IFluidDataStorePolicies,
 	type MinimumVersionForCollab,
 	asLegacyAlpha,
+	currentSummarizeStepPrefix,
+	currentSummarizeStepPropertyName,
 } from "@fluidframework/runtime-definitions/internal";
 import {
 	GCDataBuilder,
@@ -1557,6 +1559,7 @@ export const mixinRequestHandler = (
 export const mixinSummaryHandler = (
 	handler: (
 		runtime: FluidDataStoreRuntime,
+		setCurrentSummarizeStep: (currentStep: string) => void,
 	) => Promise<{ path: string[]; content: string } | undefined>,
 	Base: typeof FluidDataStoreRuntime = FluidDataStoreRuntime,
 ): typeof FluidDataStoreRuntime =>
@@ -1584,12 +1587,21 @@ export const mixinSummaryHandler = (
 			summary.summary.tree[firstName] = blob;
 		}
 
-		async summarize(...args: any[]): Promise<ISummaryTreeWithStats> {
-			// eslint-disable-next-line @typescript-eslint/no-unsafe-argument
-			const summary = await super.summarize(...args);
+		async summarize(
+			fullTree: boolean = false,
+			trackState: boolean = true,
+			telemetryContext?: ITelemetryContext,
+		): Promise<ISummaryTreeWithStats> {
+			const summary = await super.summarize(fullTree, trackState, telemetryContext);
 
 			try {
-				const content = await handler(this);
+				const content = await handler(this, (currentStep: string) =>
+					telemetryContext?.set(
+						currentSummarizeStepPrefix,
+						currentSummarizeStepPropertyName,
+						`mixinSummaryHandler:${currentStep}`,
+					),
+				);
 				if (content !== undefined) {
 					this.addBlob(summary, content.path, content.content);
 				}

packages/runtime/runtime-definitions/src/index.ts

@@ -89,6 +89,8 @@ export {
 	channelsTreeName,
 	CreateSummarizerNodeSource,
 	totalBlobSizePropertyName,
+	currentSummarizeStepPrefix,
+	currentSummarizeStepPropertyName,
 } from "./summary.js";
 export type { MinimumVersionForCollab } from "./compatibilityDefinitions.js";
 

packages/runtime/runtime-definitions/src/summary.ts

@@ -387,3 +387,13 @@ export const blobCountPropertyName = "BlobCount";
  * @internal
  */
 export const totalBlobSizePropertyName = "TotalBlobSize";
+
+/**
+ * @internal
+ */
+export const currentSummarizeStepPrefix = "";
+
+/**
+ * @internal
+ */
+export const currentSummarizeStepPropertyName = "CurrentSummarizeStep";

packages/runtime/runtime-utils/src/summaryUtils.ts

@@ -32,7 +32,11 @@ import type {
 	ISummarizeResult,
 	ITelemetryContextExt,
 } from "@fluidframework/runtime-definitions/internal";
-import { gcDataBlobKey } from "@fluidframework/runtime-definitions/internal";
+import {
+	currentSummarizeStepPrefix,
+	currentSummarizeStepPropertyName,
+	gcDataBlobKey,
+} from "@fluidframework/runtime-definitions/internal";
 import type { TelemetryEventPropertyTypeExt } from "@fluidframework/telemetry-utils/internal";
 
 /**
@@ -520,14 +524,18 @@ export class TelemetryContext implements ITelemetryContext, ITelemetryContextExt
 	}
 
 	/**
-	 * {@inheritDoc @fluidframework/runtime-definitions#ITelemetryContext.get}
+	 * Get the telemetry data being tracked
+	 * @param prefix - unique prefix to tag this data with (ex: "fluid:map:")
+	 * @param property - property name of the telemetry data being tracked (ex: "DirectoryCount")
+	 * @returns undefined if item not found
 	 */
 	public get(prefix: string, property: string): TelemetryEventPropertyTypeExt {
 		return this.telemetry.get(`${prefix}${property}`);
 	}
 
 	/**
-	 * {@inheritDoc @fluidframework/runtime-definitions#ITelemetryContext.serialize}
+	 * Returns a serialized version of all the telemetry data.
+	 * Should be used when logging in telemetry events.
 	 */
 	public serialize(): string {
 		const jsonObject = {};
@@ -536,6 +544,14 @@ export class TelemetryContext implements ITelemetryContext, ITelemetryContextExt
 		}
 		return JSON.stringify(jsonObject);
 	}
+
+	public get currentSummarizeStep(): TelemetryEventPropertyTypeExt {
+		return this.get(currentSummarizeStepPrefix, currentSummarizeStepPropertyName);
+	}
+
+	public set currentSummarizeStep(value: TelemetryEventPropertyTypeExt) {
+		this.set(currentSummarizeStepPrefix, currentSummarizeStepPropertyName, value);
+	}
 }
 
 /**