From 22b4616f726cd4f181a721aeffbaeadc9d321d3f Mon Sep 17 00:00:00 2001 From: Rahim Rahman Date: Tue, 20 May 2025 12:47:29 -0600 Subject: [PATCH] feat(MM-63936): add mark function in performance metrics manager (#8823) --- .../performance_metrics_manager/index.test.ts | 29 ++++++++++++- .../performance_metrics_manager/index.ts | 41 +++++++++++++++---- 2 files changed, 62 insertions(+), 8 deletions(-) diff --git a/app/managers/performance_metrics_manager/index.test.ts b/app/managers/performance_metrics_manager/index.test.ts index 5e74d9fc5..9f065cf63 100644 --- a/app/managers/performance_metrics_manager/index.test.ts +++ b/app/managers/performance_metrics_manager/index.test.ts @@ -7,7 +7,7 @@ import performance from 'react-native-performance'; import {mockApiClient} from '@test/mock_api_client'; import TestHelper from '@test/test_helper'; -import {logWarning} from '@utils/log'; +import {logInfo, logWarning} from '@utils/log'; import NetworkManager from '../network_manager'; @@ -28,8 +28,10 @@ const { } = batcherTestExports; const TEST_EPOCH = 1577836800000; + jest.mock('@utils/log', () => ({ logDebug: jest.fn(), + logInfo: jest.fn(), logWarning: jest.fn(), })); @@ -378,5 +380,30 @@ describe('performance_metrics_manager', () => { expect(mockApiClient.post).toHaveBeenCalledWith(expectedUrl1, expectedRequest1); expect(mockApiClient.post).toHaveBeenCalledWith(expectedUrl2, expectedRequest2); }); + + it('handles multiple marks with detailed logging', async () => { + const timestamp = TEST_EPOCH + 200; + const expectedRequest = getBaseReportRequest(timestamp, timestamp + 1); + expectedRequest.body.histograms = [{ + metric: 'mobile_channel_switch', + timestamp, + value: 50, + }]; + + PerformanceMetricsManager.startMetric('mobile_channel_switch'); + jest.advanceTimersByTime(50); + PerformanceMetricsManager.mark('mobile_channel_switch', {detail: 'middle'}); + jest.advanceTimersByTime(150); + PerformanceMetricsManager.endMetric('mobile_channel_switch', serverUrl1); + await TestHelper.tick(); + + jest.advanceTimersByTime(INTERVAL_TIME); + await TestHelper.tick(); + expect(mockApiClient.post).toHaveBeenCalledWith(expectedUrl1, expectedRequest); + + expect(logInfo).toHaveBeenCalledWith('Performance marks for mobile_channel_switch:'); + expect(logInfo).toHaveBeenCalledWith('Mark 0 => 1: 50.00ms [startMetric => middle]'); + expect(logInfo).toHaveBeenCalledWith('Total: 50.00ms'); + }); }); }); diff --git a/app/managers/performance_metrics_manager/index.ts b/app/managers/performance_metrics_manager/index.ts index 25fbf58bf..dfe0bea9b 100644 --- a/app/managers/performance_metrics_manager/index.ts +++ b/app/managers/performance_metrics_manager/index.ts @@ -5,13 +5,18 @@ import RNUtils from '@mattermost/rnutils'; import {AppState, type AppStateStatus} from 'react-native'; import performance from 'react-native-performance'; -import {logDebug, logWarning} from '@utils/log'; +import {logDebug, logInfo, logWarning} from '@utils/log'; import Batcher from './performance_metrics_batcher'; import type {NetworkRequestMetrics} from './constant'; import type {MarkOptions} from 'react-native-performance/lib/typescript/performance'; +interface PerformanceMarkWithDetail { + startTime: number; + detail?: string; +} + type Target = 'HOME' | 'CHANNEL' | 'THREAD' | undefined; type MetricName = 'mobile_channel_switch' | @@ -87,26 +92,48 @@ class PerformanceMetricsManagerSingleton { } public startMetric(metricName: MetricName) { - performance.mark(metricName); + performance.mark(metricName, {detail: 'startMetric'}); + } + + public mark(metricName: MetricName, options?: MarkOptions) { + performance.mark(metricName, options); } public endMetric(metricName: MetricName, serverUrl: string) { - const marks = performance.getEntriesByName(metricName, 'mark'); + const marks = performance.getEntriesByName(metricName, 'mark') as PerformanceMarkWithDetail[]; if (!marks.length) { return; } - const measureName = `${metricName}_measure`; - const measure = performance.measure(measureName, metricName); + let duration = 0; + if (marks.length === 1) { + const measureName = `measure_${metricName}`; + const measure = performance.measure(measureName, metricName); + duration = measure.duration; + performance.clearMeasures(measureName); + } else { + // get additional details when using mark()s + // measure() returns duration value that is not the same as the diff between the last and first mark + duration = marks[marks.length - 1].startTime - marks[0].startTime; + + logInfo(`Performance marks for ${metricName}:`); + for (let i = 1; i < marks.length; i++) { + const markDuration = marks[i].startTime - marks[i - 1].startTime; + const timeStr = markDuration.toFixed(2).padStart(8, ' '); + const markRange = `Mark ${i - 1} => ${i}:`.padEnd(15, ' '); + const details = `[${marks[i - 1].detail || 'no detail'} => ${marks[i].detail || 'no detail'}]`; + logInfo(`${markRange}${timeStr}ms ${details}`); + } + logInfo(`${'Total:'.padEnd(15, ' ')}${duration.toFixed(2).padStart(8, ' ')}ms`); + } this.ensureBatcher(serverUrl).addToBatch({ metric: metricName, - value: measure.duration, + value: duration, timestamp: Date.now(), }); performance.clearMarks(metricName); - performance.clearMeasures(measureName); } public startTimeToInteraction(options?: MarkOptions) {