feat(MM-63936): add mark function in performance metrics manager (#8823)

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

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) {