From 4ec4b4d52547a3d1382e13a475dbaff925a0bbfc Mon Sep 17 00:00:00 2001 From: Agniva De Sarker Date: Fri, 29 Nov 2024 11:24:35 +0530 Subject: [PATCH] MM-61886: Add actionable page navigation metrics (#29332) Page load is one of the metrics that we track and present to MLT. However, in its current form, it is not very actionable because it also contains the network latency. We split the whole metric into these parts: startTime | responseStart = TTFB | responseEnd = TTLB | domInteractive = Start of processing phase | loadEventEnd = Load complete This gives us better visibility into exactly which phase in the load process is slow. I have experimented with other metrics like - domContentLoadedEventStart - domContentLoadedEventEnd - domComplete and observed that they do not have sufficient gaps in the timespan to have any relevance. Additionally, I have moved TTFB from being a web vitals metric to being tracked from the performance metrics to remain consistent with the other navigation metrics measured. Lastly, I took this chance to improve some of the validation errors that we threw to include more context into the input that was passed and why does it fail. This also meant that I had to change the tests to check for error strings rather than direct errors which is a bad thing, but I don't think it's worth the effort trying to have named error variables for all of them. https://mattermost.atlassian.net/browse/MM-61886 ```release-note NONE ``` --- server/channels/app/metrics.go | 9 ++++ server/einterfaces/metrics.go | 3 ++ server/einterfaces/mocks/MetricsInterface.go | 15 ++++++ server/enterprise/metrics/metrics.go | 48 +++++++++++++++++++ server/public/model/metrics.go | 15 +++--- server/public/model/metrics_test.go | 17 ++++--- .../initial_loading_screen_class.ts | 14 +++++- webapp/channels/src/components/root/root.tsx | 2 +- .../team_controller/team_controller.tsx | 2 +- .../src/utils/performance_telemetry/index.ts | 10 ++-- .../performance_telemetry/reporter.test.ts | 8 +--- .../utils/performance_telemetry/reporter.ts | 31 +++++++++--- 12 files changed, 138 insertions(+), 36 deletions(-) diff --git a/server/channels/app/metrics.go b/server/channels/app/metrics.go index 59075755d9..1372f490f7 100644 --- a/server/channels/app/metrics.go +++ b/server/channels/app/metrics.go @@ -28,6 +28,15 @@ func (a *App) RegisterPerformanceReport(rctx request.CTX, report *model.Performa switch h.Metric { case model.ClientTimeToFirstByte: a.Metrics().ObserveClientTimeToFirstByte(commonLabels["platform"], commonLabels["agent"], h.Value/1000) + case model.ClientTimeToLastByte: + a.Metrics().ObserveClientTimeToLastByte(commonLabels["platform"], commonLabels["agent"], h.Value/1000) + case model.ClientTimeToDOMInteractive: + a.Metrics().ObserveClientTimeToDomInteractive(commonLabels["platform"], commonLabels["agent"], h.Value/1000) + case model.ClientSplashScreenEnd: + a.Metrics().ObserveClientSplashScreenEnd(commonLabels["platform"], + commonLabels["agent"], + h.GetLabelValue("page_type", model.AcceptedSplashScreenOrigins, "team_controller"), + h.Value/1000) case model.ClientFirstContentfulPaint: a.Metrics().ObserveClientFirstContentfulPaint(commonLabels["platform"], commonLabels["agent"], h.Value/1000) case model.ClientLargestContentfulPaint: diff --git a/server/einterfaces/metrics.go b/server/einterfaces/metrics.go index 38e7ec0d7e..98ca099d11 100644 --- a/server/einterfaces/metrics.go +++ b/server/einterfaces/metrics.go @@ -105,6 +105,9 @@ type MetricsInterface interface { IncrementNotificationUnsupportedCounter(notificationType model.NotificationType, notSentReason model.NotificationReason, platform string) ObserveClientTimeToFirstByte(platform, agent string, elapsed float64) + ObserveClientTimeToLastByte(platform, agent string, elapsed float64) + ObserveClientTimeToDomInteractive(platform, agent string, elapsed float64) + ObserveClientSplashScreenEnd(platform, agent, pageType string, elapsed float64) ObserveClientFirstContentfulPaint(platform, agent string, elapsed float64) ObserveClientLargestContentfulPaint(platform, agent, region string, elapsed float64) ObserveClientInteractionToNextPaint(platform, agent, interaction string, elapsed float64) diff --git a/server/einterfaces/mocks/MetricsInterface.go b/server/einterfaces/mocks/MetricsInterface.go index 13ddb1a7ff..f8e80cec3e 100644 --- a/server/einterfaces/mocks/MetricsInterface.go +++ b/server/einterfaces/mocks/MetricsInterface.go @@ -338,16 +338,31 @@ func (_m *MetricsInterface) ObserveClientRHSLoadDuration(platform string, agent _m.Called(platform, agent, elapsed) } +// ObserveClientSplashScreenEnd provides a mock function with given fields: platform, agent, pageType, elapsed +func (_m *MetricsInterface) ObserveClientSplashScreenEnd(platform string, agent string, pageType string, elapsed float64) { + _m.Called(platform, agent, pageType, elapsed) +} + // ObserveClientTeamSwitchDuration provides a mock function with given fields: platform, agent, fresh, elapsed func (_m *MetricsInterface) ObserveClientTeamSwitchDuration(platform string, agent string, fresh string, elapsed float64) { _m.Called(platform, agent, fresh, elapsed) } +// ObserveClientTimeToDomInteractive provides a mock function with given fields: platform, agent, elapsed +func (_m *MetricsInterface) ObserveClientTimeToDomInteractive(platform string, agent string, elapsed float64) { + _m.Called(platform, agent, elapsed) +} + // ObserveClientTimeToFirstByte provides a mock function with given fields: platform, agent, elapsed func (_m *MetricsInterface) ObserveClientTimeToFirstByte(platform string, agent string, elapsed float64) { _m.Called(platform, agent, elapsed) } +// ObserveClientTimeToLastByte provides a mock function with given fields: platform, agent, elapsed +func (_m *MetricsInterface) ObserveClientTimeToLastByte(platform string, agent string, elapsed float64) { + _m.Called(platform, agent, elapsed) +} + // ObserveClusterRequestDuration provides a mock function with given fields: elapsed func (_m *MetricsInterface) ObserveClusterRequestDuration(elapsed float64) { _m.Called(elapsed) diff --git a/server/enterprise/metrics/metrics.go b/server/enterprise/metrics/metrics.go index 688ef96a68..4e79279cef 100644 --- a/server/enterprise/metrics/metrics.go +++ b/server/enterprise/metrics/metrics.go @@ -202,6 +202,9 @@ type MetricsInterfaceImpl struct { NotificationUnsupportedCounters *prometheus.CounterVec ClientTimeToFirstByte *prometheus.HistogramVec + ClientTimeToLastByte *prometheus.HistogramVec + ClientTimeToDOMInteractive *prometheus.HistogramVec + ClientSplashScreenEnd *prometheus.HistogramVec ClientFirstContentfulPaint *prometheus.HistogramVec ClientLargestContentfulPaint *prometheus.HistogramVec ClientInteractionToNextPaint *prometheus.HistogramVec @@ -1187,6 +1190,39 @@ func New(ps *platform.PlatformService, driver, dataSource string) *MetricsInterf ) m.Registry.MustRegister(m.ClientTimeToFirstByte) + m.ClientTimeToLastByte = prometheus.NewHistogramVec( + prometheus.HistogramOpts{ + Namespace: MetricsNamespace, + Subsystem: MetricsSubsystemClientsWeb, + Name: "time_to_last_byte", + Help: "Duration from when a browser starts to request a page from a server until when it receives the last byte of the resource or immediately before the transport connection is closed, whichever comes first. (seconds)", + }, + []string{"platform", "agent"}, + ) + m.Registry.MustRegister(m.ClientTimeToLastByte) + + m.ClientTimeToDOMInteractive = prometheus.NewHistogramVec( + prometheus.HistogramOpts{ + Namespace: MetricsNamespace, + Subsystem: MetricsSubsystemClientsWeb, + Name: "dom_interactive", + Help: "Duration from when a browser starts to request a page from a server until when it sets the document's readyState to interactive. (seconds)", + }, + []string{"platform", "agent"}, + ) + m.Registry.MustRegister(m.ClientTimeToDOMInteractive) + + m.ClientSplashScreenEnd = prometheus.NewHistogramVec( + prometheus.HistogramOpts{ + Namespace: MetricsNamespace, + Subsystem: MetricsSubsystemClientsWeb, + Name: "splash_screen", + Help: "Duration from when a browser starts to request a page from a server until when the splash screen ends. (seconds)", + }, + []string{"platform", "agent", "page_type"}, + ) + m.Registry.MustRegister(m.ClientSplashScreenEnd) + m.ClientFirstContentfulPaint = prometheus.NewHistogramVec( prometheus.HistogramOpts{ Namespace: MetricsNamespace, @@ -1838,6 +1874,18 @@ func (mi *MetricsInterfaceImpl) ObserveClientTimeToFirstByte(platform, agent str mi.ClientTimeToFirstByte.With(prometheus.Labels{"platform": platform, "agent": agent}).Observe(elapsed) } +func (mi *MetricsInterfaceImpl) ObserveClientTimeToLastByte(platform, agent string, elapsed float64) { + mi.ClientTimeToLastByte.With(prometheus.Labels{"platform": platform, "agent": agent}).Observe(elapsed) +} + +func (mi *MetricsInterfaceImpl) ObserveClientTimeToDomInteractive(platform, agent string, elapsed float64) { + mi.ClientTimeToDOMInteractive.With(prometheus.Labels{"platform": platform, "agent": agent}).Observe(elapsed) +} + +func (mi *MetricsInterfaceImpl) ObserveClientSplashScreenEnd(platform, agent, pageType string, elapsed float64) { + mi.ClientSplashScreenEnd.With(prometheus.Labels{"platform": platform, "agent": agent, "page_type": pageType}).Observe(elapsed) +} + func (mi *MetricsInterfaceImpl) ObserveClientFirstContentfulPaint(platform, agent string, elapsed float64) { mi.ClientFirstContentfulPaint.With(prometheus.Labels{"platform": platform, "agent": agent}).Observe(elapsed) } diff --git a/server/public/model/metrics.go b/server/public/model/metrics.go index e8e47912df..a6e6f3ff55 100644 --- a/server/public/model/metrics.go +++ b/server/public/model/metrics.go @@ -6,7 +6,6 @@ package model import ( "fmt" "strings" - "time" "github.com/blang/semver/v4" ) @@ -15,6 +14,9 @@ type MetricType string const ( ClientTimeToFirstByte MetricType = "TTFB" + ClientTimeToLastByte MetricType = "TTLB" + ClientTimeToDOMInteractive MetricType = "dom_interactive" + ClientSplashScreenEnd MetricType = "splash_screen" ClientFirstContentfulPaint MetricType = "FCP" ClientLargestContentfulPaint MetricType = "LCP" ClientInteractionToNextPaint MetricType = "INP" @@ -54,7 +56,8 @@ var ( "modal_content", "other", ) - AcceptedTrueFalseLabels = sliceToMapKey("true", "false") + AcceptedTrueFalseLabels = sliceToMapKey("true", "false") + AcceptedSplashScreenOrigins = sliceToMapKey("root", "team_controller") ) type MetricSample struct { @@ -86,7 +89,7 @@ func (r *PerformanceReport) IsValid() error { reportVersion, err := semver.ParseTolerant(r.Version) if err != nil { - return err + return fmt.Errorf("could not parse semver version: %s, %w", r.Version, err) } if reportVersion.Major != performanceReportVersion.Major || reportVersion.Minor > performanceReportVersion.Minor { @@ -94,12 +97,12 @@ func (r *PerformanceReport) IsValid() error { } if r.Start > r.End { - return fmt.Errorf("report timestamps are erroneous") + return fmt.Errorf("report timestamps are erroneous: start_timestamp %f is greater than end_timestamp %f", r.Start, r.End) } - now := time.Now().UnixMilli() + now := GetMillis() if r.End < float64(now-performanceReportTTLMilliseconds) { - return fmt.Errorf("report is outdated: %f", r.End) + return fmt.Errorf("report is outdated: end_time %f is past %d ms from now", r.End, performanceReportTTLMilliseconds) } return nil diff --git a/server/public/model/metrics_test.go b/server/public/model/metrics_test.go index 5de3484d68..cb5026105d 100644 --- a/server/public/model/metrics_test.go +++ b/server/public/model/metrics_test.go @@ -4,7 +4,6 @@ package model import ( - "fmt" "testing" "time" @@ -16,7 +15,7 @@ func TestPerformanceReport_IsValid(t *testing.T) { tests := []struct { name string report *PerformanceReport - expected error + expected string }{ { name: "ValidReport", @@ -26,12 +25,12 @@ func TestPerformanceReport_IsValid(t *testing.T) { Start: float64(time.Now().UnixMilli() - 10000), End: float64(time.Now().UnixMilli()), }, - expected: nil, + expected: "", }, { name: "NilReport", report: nil, - expected: fmt.Errorf("the report is nil"), + expected: "the report is nil", }, { name: "UnsupportedVersion", @@ -41,7 +40,7 @@ func TestPerformanceReport_IsValid(t *testing.T) { Start: float64(time.Now().UnixMilli() - 10000), End: float64(time.Now().UnixMilli()), }, - expected: fmt.Errorf("report version is not supported: server version: 0.1.0, report version: 2.0.0"), + expected: "report version is not supported:", }, { name: "ErroneousTimestamps", @@ -51,7 +50,7 @@ func TestPerformanceReport_IsValid(t *testing.T) { Start: float64(time.Now().UnixMilli()), End: float64(time.Now().Add(-1 * time.Hour).UnixMilli()), }, - expected: fmt.Errorf("report timestamps are erroneous"), + expected: "report timestamps are erroneous", }, { name: "OutdatedReport", @@ -61,15 +60,15 @@ func TestPerformanceReport_IsValid(t *testing.T) { Start: float64(time.Now().Add(-7 * time.Minute).UnixMilli()), End: float64(outdatedTimestamp), }, - expected: fmt.Errorf("report is outdated: %f", float64(outdatedTimestamp)), + expected: "report is outdated:", }, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { err := tt.report.IsValid() - if tt.expected != nil { - require.EqualError(t, err, tt.expected.Error()) + if tt.expected != "" { + require.Contains(t, err.Error(), tt.expected) return } require.NoError(t, err) diff --git a/webapp/channels/src/components/initial_loading_screen/initial_loading_screen_class.ts b/webapp/channels/src/components/initial_loading_screen/initial_loading_screen_class.ts index 4e1f6c9805..4be5d586bf 100644 --- a/webapp/channels/src/components/initial_loading_screen/initial_loading_screen_class.ts +++ b/webapp/channels/src/components/initial_loading_screen/initial_loading_screen_class.ts @@ -1,6 +1,7 @@ // Copyright (c) 2015-present Mattermost, Inc. All Rights Reserved. // See LICENSE.txt for license information. +import {Measure, measureAndReport} from 'utils/performance_telemetry'; import {isDesktopApp} from 'utils/user_agent'; const ANIMATION_CLASS_FOR_MATTERMOST_LOGO_HIDE = 'LoadingAnimation__compass-shrink'; @@ -99,7 +100,7 @@ export class InitialLoadingScreenClass { /** * The loading animations are always started as soon as the loading indicator is shown in the screen for the first time. - * But we still want to have this start method incase we need to start the loading animations manually any time. + * But we still want to have this start method in case we need to start the loading animations manually any time. * If we do want to do that then we should remove the set timeout destroy call doing above. */ public start() { @@ -115,7 +116,7 @@ export class InitialLoadingScreenClass { this.loadingAnimationElement.className = LOADING_CLASS_FOR_ANIMATION; } - public stop() { + public stop(pageType: string) { if (!this.loadingScreenElement || !this.loadingAnimationElement) { return; } @@ -124,6 +125,15 @@ export class InitialLoadingScreenClass { this.loadingScreenElement.className = LOADING_COMPLETE_CLASS_FOR_SCREEN; this.loadingAnimationElement.className = LOADING_COMPLETE_CLASS_FOR_ANIMATION; + + measureAndReport({ + name: Measure.SplashScreen, + startMark: 0, + canFail: false, + labels: { + page_type: pageType, + }, + }); } } diff --git a/webapp/channels/src/components/root/root.tsx b/webapp/channels/src/components/root/root.tsx index 8a1809927c..de30d7626b 100644 --- a/webapp/channels/src/components/root/root.tsx +++ b/webapp/channels/src/components/root/root.tsx @@ -293,7 +293,7 @@ export default class Root extends React.PureComponent { if (prevState.shouldMountAppRoutes === false && this.state.shouldMountAppRoutes === true) { if (!doesRouteBelongToTeamControllerRoutes(this.props.location.pathname)) { DesktopApp.reactAppInitialized(); - InitialLoadingScreen.stop(); + InitialLoadingScreen.stop('root'); } } } diff --git a/webapp/channels/src/components/team_controller/team_controller.tsx b/webapp/channels/src/components/team_controller/team_controller.tsx index 77c3840999..e6074a440a 100644 --- a/webapp/channels/src/components/team_controller/team_controller.tsx +++ b/webapp/channels/src/components/team_controller/team_controller.tsx @@ -55,7 +55,7 @@ function TeamController(props: Props) { useTelemetryIdentitySync(); useEffect(() => { - InitialLoadingScreen.stop(); + InitialLoadingScreen.stop('team_controller'); DesktopApp.reactAppInitialized(); async function fetchAllChannels() { await props.fetchAllMyTeamsChannels(); diff --git a/webapp/channels/src/utils/performance_telemetry/index.ts b/webapp/channels/src/utils/performance_telemetry/index.ts index 9e9966c0eb..ac2bc92db8 100644 --- a/webapp/channels/src/utils/performance_telemetry/index.ts +++ b/webapp/channels/src/utils/performance_telemetry/index.ts @@ -13,6 +13,10 @@ export const enum Measure { ChannelSwitch = 'channel_switch', GlobalThreadsLoad = 'global_threads_load', PageLoad = 'page_load', + TTFB = 'TTFB', + TTLB = 'TTLB', + SplashScreen = 'splash_screen', + DomInteractive = 'dom_interactive', RhsLoad = 'rhs_load', TeamSwitch = 'team_switch', } @@ -29,7 +33,7 @@ export function markAndReport(name: string): PerformanceMark { * Measures the duration between two performance marks, schedules it to be reported to the server, and returns the * PerformanceMeasure created by doing this. If endMark is omitted, the measure will measure the duration until now. * - * If either the start or end mark does not exist, undefined will be returned and, if canFail is false, an error + * If either the start or end mark does not exist, undefined will be returned, and if canFail is false, an error * will be logged. */ export function measureAndReport({ @@ -40,8 +44,8 @@ export function measureAndReport({ canFail = false, }: { name: string; - startMark: string; - endMark?: string; + startMark: string | DOMHighResTimeStamp; + endMark?: string | DOMHighResTimeStamp; labels?: Record; canFail?: boolean; }): PerformanceMeasure | undefined { diff --git a/webapp/channels/src/utils/performance_telemetry/reporter.test.ts b/webapp/channels/src/utils/performance_telemetry/reporter.test.ts index 888386c8b6..07d177095c 100644 --- a/webapp/channels/src/utils/performance_telemetry/reporter.test.ts +++ b/webapp/channels/src/utils/performance_telemetry/reporter.test.ts @@ -2,7 +2,7 @@ // See LICENSE.txt for license information. import nock from 'nock'; -import {onCLS, onFCP, onINP, onLCP, onTTFB} from 'web-vitals/attribution'; +import {onCLS, onFCP, onINP, onLCP} from 'web-vitals/attribution'; import {Client4} from '@mattermost/client'; @@ -216,8 +216,6 @@ describe.skip('PerformanceReporter', () => { onINPCallback({name: 'INP', value: 200}); const onLCPCallback = (onLCP as jest.Mock).mock.calls[0][0]; onLCPCallback({name: 'LCP', value: 2500, entries: []}); - const onTTFBCallback = (onTTFB as jest.Mock).mock.calls[0][0]; - onTTFBCallback({name: 'TTFB', value: 800}); await waitForReport(); @@ -234,10 +232,6 @@ describe.skip('PerformanceReporter', () => { metric: 'LCP', value: 2500, }, - { - metric: 'TTFB', - value: 800, - }, ], }); diff --git a/webapp/channels/src/utils/performance_telemetry/reporter.ts b/webapp/channels/src/utils/performance_telemetry/reporter.ts index af2a9237e6..e3aaaa4bd9 100644 --- a/webapp/channels/src/utils/performance_telemetry/reporter.ts +++ b/webapp/channels/src/utils/performance_telemetry/reporter.ts @@ -2,7 +2,7 @@ // See LICENSE.txt for license information. import type {Store} from 'redux'; -import {onCLS, onFCP, onINP, onLCP, onTTFB} from 'web-vitals/attribution'; +import {onCLS, onFCP, onINP, onLCP} from 'web-vitals/attribution'; import type {INPMetricWithAttribution, LCPMetricWithAttribution, Metric} from 'web-vitals/attribution'; import type {Client4} from '@mattermost/client'; @@ -114,16 +114,15 @@ export default class PerformanceReporter { entryTypes: observedEntryTypes, }); - // Record the page load separately because it arrived before we were observing and because you can't use + // Record the page navigation separately because it arrived before we were observing and because you can't use // the buffered option for PerformanceObserver with multiple entry types. - this.measurePageLoad(); + this.measurePageNavigation(); // Register handlers for standard metrics and Web Vitals onCLS((metric) => this.handleWebVital(metric)); onFCP((metric) => this.handleWebVital(metric)); onINP((metric) => this.handleWebVital(metric)); onLCP((metric) => this.handleWebVital(metric)); - onTTFB((metric) => this.handleWebVital(metric)); // Periodically send performance telemetry to the server, roughly every minute but with some randomness to // avoid overloading the server every minute. @@ -138,17 +137,35 @@ export default class PerformanceReporter { } } - private measurePageLoad() { + private measurePageNavigation() { const entries = performance.getEntriesByType('navigation'); if (entries.length === 0) { return; } + const entry = entries[0]; + const ts = Date.now(); + + this.histogramMeasures.push({ + metric: Measure.TTFB, + value: entry.responseStart, + timestamp: ts, + }); + this.histogramMeasures.push({ + metric: Measure.TTLB, + value: entry.responseEnd, + timestamp: ts, + }); + this.histogramMeasures.push({ + metric: Measure.DomInteractive, + value: entry.domInteractive, + timestamp: ts, + }); this.histogramMeasures.push({ metric: Measure.PageLoad, - value: entries[0].duration, - timestamp: Date.now(), + value: entry.duration, + timestamp: ts, }); }