Wenghe/sdk perf event (#1848)

* videoExtensibilityFirstFrameProcessed event

* videoExtensibilityTextureStreamAcquired event

* rename file

* first version of PerformanceStatistics

* integrate PerformanceStatistics

* add UT

* fix compilation error

* add ut

* Fix UT

* add UT

* slow event impl + ut

* improve UT with jest.useFakeTimers

* return when currentSelectedEffect is not initiated

* don't handle effect change twice

* fix ssr

* remove unnecessary file

* Change files

* update event names

* setFrameProcessTimeLimit

* remove magic number

* fix UT

* Update @microsoft-teams-js-4885f2ff-afee-4756-9192-4731c184d1ba.json

* rename performanceStatistics.ts

* rename class and remove magic number

* Fix typo

* add UT to ensure videoPerformanceMonitor is correctly called

* apply review suggestion

* Fix failing UT

* not use window.setTimeout/setInterval

* fix UT

* remove inServerSideRenderingEnvironment from constructor

* udpate videoEx UT

* Fix: send firstFrameProcessed with the last selected effect

* move files

* update setFrameProcessTimeLimit handling

* fix UT

* fix setInterval logic

* delay monitoring slow event

* update UT

* remove wrong content

* Fix UT

* add comments and fix typo

* handle effectParam

---------

Co-authored-by: Herbert Weng <[email protected]>
Co-authored-by: Trevor Harris <[email protected]>

change/@microsoft-teams-js-4885f2ff-afee-4756-9192-4731c184d1ba.json

@@ -0,0 +1,7 @@
+{
+  "type": "patch",
+  "comment": "Started collection of `video` performance data",
+  "packageName": "@microsoft/teams-js",
+  "email": "[email protected]",
+  "dependentChangeType": "patch"
+}

packages/teams-js/src/internal/videoFrameTick.ts

@@ -0,0 +1,56 @@
+import { generateGUID } from './utils';
+
+export class VideoFrameTick {
+  private static readonly setTimeoutCallbacks: {
+    [key: string]: {
+      callback: () => void;
+      startedAtInMs: number;
+      timeoutInMs: number;
+    };
+  } = {};
+
+  public static setTimeout(callback: () => void, timeoutInMs: number): string {
+    const startedAtInMs = performance.now();
+    const id = generateGUID();
+    VideoFrameTick.setTimeoutCallbacks[id] = {
+      callback,
+      timeoutInMs,
+      startedAtInMs,
+    };
+    return id;
+  }
+
+  public static clearTimeout(id: string): void {
+    delete VideoFrameTick.setTimeoutCallbacks[id];
+  }
+
+  public static setInterval(callback: () => void, intervalInMs: number): void {
+    VideoFrameTick.setTimeout(function next() {
+      callback();
+      VideoFrameTick.setTimeout(next, intervalInMs);
+    }, intervalInMs);
+  }
+
+  /**
+   * Call this function whenever a frame comes in, it will check if any timeout is due and call the callback
+   */
+  public static tick(): void {
+    const now = performance.now();
+    const timeoutIds = [];
+    // find all the timeouts that are due,
+    // not to invoke them in the loop to avoid modifying the collection while iterating
+    for (const key in VideoFrameTick.setTimeoutCallbacks) {
+      const callback = VideoFrameTick.setTimeoutCallbacks[key];
+      const start = callback.startedAtInMs;
+      if (now - start >= callback.timeoutInMs) {
+        timeoutIds.push(key);
+      }
+    }
+    // invoke the callbacks
+    for (const id of timeoutIds) {
+      const callback = VideoFrameTick.setTimeoutCallbacks[id];
+      callback.callback();
+      delete VideoFrameTick.setTimeoutCallbacks[id];
+    }
+  }
+}

packages/teams-js/src/internal/videoPerformanceMonitor.ts

@@ -0,0 +1,154 @@
+import { VideoFrameTick } from './videoFrameTick';
+import { VideoPerformanceStatistics } from './videoPerformanceStatistics';
+
+/**
+ * This class is used to monitor the performance of video processing, and report performance events.
+ */
+export class VideoPerformanceMonitor {
+  private static readonly distributionBinSize = 1000;
+  private static readonly calculateFPSInterval = 1000;
+
+  private isFirstFrameProcessed = false;
+
+  // The effect that the user last selected:
+  private applyingEffect: {
+    effectId: string;
+    effectParam?: string;
+  };
+
+  // The effect that is currently applied to the video:
+  private appliedEffect: {
+    effectId: string;
+    effectParam?: string;
+  };
+
+  private frameProcessTimeLimit = 100;
+  private gettingTextureStreamStartedAt: number;
+  private currentStreamId: string;
+  private frameProcessingStartedAt = 0;
+  private frameProcessingTimeCost = 0;
+  private processedFrameCount = 0;
+
+  private performanceStatistics: VideoPerformanceStatistics;
+
+  public constructor(private reportPerformanceEvent: (actionName: string, args: unknown[]) => void) {
+    this.performanceStatistics = new VideoPerformanceStatistics(VideoPerformanceMonitor.distributionBinSize, (result) =>
+      this.reportPerformanceEvent('video.performance.performanceDataGenerated', [result]),
+    );
+  }
+
+  /**
+   * Start to check frame processing time intervally
+   * and report performance event if the average frame processing time is too long.
+   */
+  public startMonitorSlowFrameProcessing(): void {
+    VideoFrameTick.setInterval(() => {
+      if (this.processedFrameCount === 0) {
+        return;
+      }
+      const averageFrameProcessingTime = this.frameProcessingTimeCost / this.processedFrameCount;
+      if (averageFrameProcessingTime > this.frameProcessTimeLimit) {
+        this.reportPerformanceEvent('video.performance.frameProcessingSlow', [averageFrameProcessingTime]);
+      }
+      this.frameProcessingTimeCost = 0;
+      this.processedFrameCount = 0;
+    }, VideoPerformanceMonitor.calculateFPSInterval);
+  }
+
+  /**
+   * Define the time limit of frame processing.
+   * When the average frame processing time is longer than the time limit, a "video.performance.frameProcessingSlow" event will be reported.
+   * @param timeLimit
+   */
+  public setFrameProcessTimeLimit(timeLimit: number): void {
+    this.frameProcessTimeLimit = timeLimit;
+  }
+
+  /**
+   * Call this function when the app starts to switch to the new video effect
+   */
+  public reportApplyingVideoEffect(effectId: string, effectParam?: string): void {
+    if (this.applyingEffect?.effectId === effectId && this.applyingEffect?.effectParam === effectParam) {
+      return;
+    }
+    this.applyingEffect = {
+      effectId,
+      effectParam,
+    };
+    this.appliedEffect = undefined;
+  }
+
+  /**
+   * Call this function when the new video effect is ready
+   */
+  public reportVideoEffectChanged(effectId: string, effectParam?: string): void {
+    if (
+      this.applyingEffect === undefined ||
+      (this.applyingEffect.effectId !== effectId && this.applyingEffect.effectParam !== effectParam)
+    ) {
+      // don't handle obsoleted event
+      return;
+    }
+    this.appliedEffect = {
+      effectId,
+      effectParam,
+    };
+    this.applyingEffect = undefined;
+    this.isFirstFrameProcessed = false;
+  }
+
+  /**
+   * Call this function when the app starts to process a video frame
+   */
+  public reportStartFrameProcessing(frameWidth: number, frameHeight: number): void {
+    VideoFrameTick.tick();
+    if (!this.appliedEffect) {
+      return;
+    }
+    this.frameProcessingStartedAt = performance.now();
+    this.performanceStatistics.processStarts(
+      this.appliedEffect.effectId,
+      frameWidth,
+      frameHeight,
+      this.appliedEffect.effectParam,
+    );
+  }
+
+  /**
+   * Call this function when the app finishes successfully processing a video frame
+   */
+  public reportFrameProcessed(): void {
+    if (!this.appliedEffect) {
+      return;
+    }
+    this.processedFrameCount++;
+    this.frameProcessingTimeCost += performance.now() - this.frameProcessingStartedAt;
+    this.performanceStatistics.processEnds();
+    if (!this.isFirstFrameProcessed) {
+      this.isFirstFrameProcessed = true;
+      this.reportPerformanceEvent('video.performance.firstFrameProcessed', [
+        Date.now(),
+        this.appliedEffect.effectId,
+        this.appliedEffect?.effectParam,
+      ]);
+    }
+  }
+
+  /**
+   * Call this function when the app starts to get the texture stream
+   */
+  public reportGettingTextureStream(streamId: string): void {
+    this.gettingTextureStreamStartedAt = performance.now();
+    this.currentStreamId = streamId;
+  }
+
+  /**
+   * Call this function when the app finishes successfully getting the texture stream
+   */
+  public reportTextureStreamAcquired(): void {
+    if (this.gettingTextureStreamStartedAt !== undefined) {
+      const timeTaken = performance.now() - this.gettingTextureStreamStartedAt;
+      this.reportPerformanceEvent('video.performance.textureStreamAcquired', [this.currentStreamId, timeTaken]);
+    }
+  }
+}

packages/teams-js/src/internal/videoPerformanceStatistics.ts

@@ -0,0 +1,152 @@
+import { VideoFrameTick } from './videoFrameTick';
+
+export type VideoPerformanceStatisticsResult = {
+  effectId: string;
+  effectParam?: string;
+  frameWidth: number;
+  frameHeight: number;
+  /**
+   * The duration in milliseconds that the data were collected
+   */
+  duration: number;
+  /**
+   * The number of frames that were processed in the duration
+   */
+  sampleCount: number;
+  /**
+   * An array that presents counts of frames that were finished in n milliseconds:
+   * distributionBins[frameProcessingDurationInMs]=frameCount.
+   * For example, distributionBins[10] = 5 means that 5 frames were processed in 10 milliseconds.
+   */
+  distributionBins: Uint32Array;
+};
+
+export class VideoPerformanceStatistics {
+  private static readonly initialSessionTimeoutInMs = 1000;
+  private static readonly maxSessionTimeoutInMs = 1000 * 30;
+
+  private currentSession: {
+    startedAtInMs: number;
+    timeoutInMs: number;
+    effectId: string;
+    effectParam?: string;
+    frameWidth: number;
+    frameHeight: number;
+  };
+
+  private frameProcessingStartedAt: number;
+  private distributionBins: Uint32Array;
+  private sampleCount = 0;
+  private timeoutId: string;
+
+  public constructor(
+    distributionBinSize: number,
+    /**
+     * Function to report the statistics result
+     */
+    private reportStatisticsResult: (result: VideoPerformanceStatisticsResult) => void,
+  ) {
+    this.distributionBins = new Uint32Array(distributionBinSize);
+  }
+
+  /**
+   * Call this function before processing every frame
+   */
+  public processStarts(effectId: string, frameWidth: number, frameHeight: number, effectParam?: string): void {
+    VideoFrameTick.tick();
+    if (!this.suitableForThisSession(effectId, frameWidth, frameHeight, effectParam)) {
+      this.reportAndResetSession(this.getStatistics(), effectId, effectParam, frameWidth, frameHeight);
+    }
+    this.start();
+  }
+
+  public processEnds(): void {
+    // calculate duration of the process and record it
+    const durationInMillisecond = performance.now() - this.frameProcessingStartedAt;
+    const binIndex = Math.floor(Math.max(0, Math.min(this.distributionBins.length - 1, durationInMillisecond)));
+    this.distributionBins[binIndex] += 1;
+    this.sampleCount += 1;
+  }
+
+  private getStatistics(): VideoPerformanceStatisticsResult {
+    if (!this.currentSession) {
+      return null;
+    }
+    return {
+      effectId: this.currentSession.effectId,
+      effectParam: this.currentSession.effectParam,
+      frameHeight: this.currentSession.frameHeight,
+      frameWidth: this.currentSession.frameWidth,
+      duration: performance.now() - this.currentSession.startedAtInMs,
+      sampleCount: this.sampleCount,
+      distributionBins: this.distributionBins.slice(),
+    };
+  }
+
+  private start(): void {
+    this.frameProcessingStartedAt = performance.now();
+  }
+
+  private suitableForThisSession(
+    effectId: string,
+    frameWidth: number,
+    frameHeight: number,
+    effectParam?: string,
+  ): boolean {
+    return (
+      this.currentSession &&
+      this.currentSession.effectId === effectId &&
+      this.currentSession.effectParam === effectParam &&
+      this.currentSession.frameWidth === frameWidth &&
+      this.currentSession.frameHeight === frameHeight
+    );
+  }
+
+  private reportAndResetSession(result, effectId, effectParam, frameWidth, frameHeight): void {
+    result && this.reportStatisticsResult(result);
+    this.resetCurrentSession(
+      this.getNextTimeout(effectId, this.currentSession),
+      effectId,
+      effectParam,
+      frameWidth,
+      frameHeight,
+    );
+    if (this.timeoutId) {
+      VideoFrameTick.clearTimeout(this.timeoutId);
+    }
+    this.timeoutId = VideoFrameTick.setTimeout(
+      (() => this.reportAndResetSession(this.getStatistics(), effectId, effectParam, frameWidth, frameHeight)).bind(
+        this,
+      ),
+      this.currentSession.timeoutInMs,
+    );
+  }
+
+  private resetCurrentSession(
+    timeoutInMs: number,
+    effectId: string,
+    effectParam: string,
+    frameWidth: number,
+    frameHeight: number,
+  ): void {
+    this.currentSession = {
+      startedAtInMs: performance.now(),
+      timeoutInMs,
+      effectId,
+      effectParam,
+      frameWidth,
+      frameHeight,
+    };
+    this.sampleCount = 0;
+    this.distributionBins.fill(0);
+  }
+
+  // send the statistics result every n second, where n starts from 1, 2, 4...and finally stays at every 30 seconds.
+  private getNextTimeout(effectId: string, currentSession?: { timeoutInMs: number; effectId: string }): number {
+    // only reset timeout when new session or effect changed
+    if (!currentSession || currentSession.effectId !== effectId) {
+      return VideoPerformanceStatistics.initialSessionTimeoutInMs;
+    }
+    return Math.min(VideoPerformanceStatistics.maxSessionTimeoutInMs, currentSession.timeoutInMs * 2);
+  }
+}