MM-61887: Log the userID if a metric exceeds the last histogram bucket (#29448)

We create a custom histogram metric that logs the userID
when the observed value is greater or equal to the last bucket value.

This allows us to start tracking the slowest users of a system
while at the same time not polluting the Prometheus metrics
by storing a userID for every observation.

https://mattermost.atlassian.net/browse/MM-61887

```release-note
NONE
```
This commit is contained in:
Agniva De Sarker
2024-12-05 09:12:54 +05:30
committed by GitHub
parent 421001c981
commit a6d37fa14c
7 changed files with 203 additions and 63 deletions
+39 -20
View File
@@ -14,6 +14,7 @@ func (a *App) RegisterPerformanceReport(rctx request.CTX, report *model.Performa
}
commonLabels := report.ProcessLabels()
userID := rctx.Session().UserId
for _, c := range report.Counters {
switch c.Metric {
@@ -27,60 +28,78 @@ func (a *App) RegisterPerformanceReport(rctx request.CTX, report *model.Performa
for _, h := range report.Histograms {
switch h.Metric {
case model.ClientTimeToFirstByte:
a.Metrics().ObserveClientTimeToFirstByte(commonLabels["platform"], commonLabels["agent"], h.Value/1000)
a.Metrics().ObserveClientTimeToFirstByte(
commonLabels["platform"],
commonLabels["agent"],
userID, h.Value/1000)
case model.ClientTimeToLastByte:
a.Metrics().ObserveClientTimeToLastByte(commonLabels["platform"], commonLabels["agent"], h.Value/1000)
a.Metrics().ObserveClientTimeToLastByte(
commonLabels["platform"],
commonLabels["agent"],
userID, h.Value/1000)
case model.ClientTimeToDOMInteractive:
a.Metrics().ObserveClientTimeToDomInteractive(commonLabels["platform"], commonLabels["agent"], h.Value/1000)
a.Metrics().ObserveClientTimeToDomInteractive(
commonLabels["platform"],
commonLabels["agent"],
userID, h.Value/1000)
case model.ClientSplashScreenEnd:
a.Metrics().ObserveClientSplashScreenEnd(commonLabels["platform"],
commonLabels["agent"],
h.GetLabelValue("page_type", model.AcceptedSplashScreenOrigins, "team_controller"),
h.Value/1000)
userID, h.Value/1000)
case model.ClientFirstContentfulPaint:
a.Metrics().ObserveClientFirstContentfulPaint(commonLabels["platform"], commonLabels["agent"], h.Value/1000)
a.Metrics().ObserveClientFirstContentfulPaint(commonLabels["platform"],
commonLabels["agent"],
h.Value/1000)
case model.ClientLargestContentfulPaint:
a.Metrics().ObserveClientLargestContentfulPaint(
commonLabels["platform"],
commonLabels["agent"],
h.GetLabelValue("region", model.AcceptedLCPRegions, "other"),
h.Value/1000,
)
h.Value/1000)
case model.ClientInteractionToNextPaint:
a.Metrics().ObserveClientInteractionToNextPaint(
commonLabels["platform"],
commonLabels["agent"],
h.GetLabelValue("interaction", model.AcceptedInteractions, "other"),
h.Value/1000,
)
h.Value/1000)
case model.ClientCumulativeLayoutShift:
a.Metrics().ObserveClientCumulativeLayoutShift(commonLabels["platform"], commonLabels["agent"], h.Value)
a.Metrics().ObserveClientCumulativeLayoutShift(commonLabels["platform"],
commonLabels["agent"],
h.Value)
case model.ClientPageLoadDuration:
a.Metrics().ObserveClientPageLoadDuration(commonLabels["platform"], commonLabels["agent"], h.Value/1000)
a.Metrics().ObserveClientPageLoadDuration(commonLabels["platform"],
commonLabels["agent"],
userID, h.Value/1000)
case model.ClientChannelSwitchDuration:
a.Metrics().ObserveClientChannelSwitchDuration(
commonLabels["platform"],
commonLabels["agent"],
h.GetLabelValue("fresh", model.AcceptedTrueFalseLabels, ""),
h.Value/1000,
)
h.Value/1000)
case model.ClientTeamSwitchDuration:
a.Metrics().ObserveClientTeamSwitchDuration(
commonLabels["platform"],
commonLabels["agent"],
h.GetLabelValue("fresh", model.AcceptedTrueFalseLabels, ""),
h.Value/1000,
)
h.Value/1000)
case model.ClientRHSLoadDuration:
a.Metrics().ObserveClientRHSLoadDuration(commonLabels["platform"], commonLabels["agent"], h.Value/1000)
a.Metrics().ObserveClientRHSLoadDuration(commonLabels["platform"],
commonLabels["agent"],
h.Value/1000)
case model.ClientGlobalThreadsLoadDuration:
a.Metrics().ObserveGlobalThreadsLoadDuration(commonLabels["platform"], commonLabels["agent"], h.Value/1000)
a.Metrics().ObserveGlobalThreadsLoadDuration(commonLabels["platform"],
commonLabels["agent"],
h.Value/1000)
case model.MobileClientLoadDuration:
a.Metrics().ObserveMobileClientLoadDuration(commonLabels["platform"], h.Value/1000)
a.Metrics().ObserveMobileClientLoadDuration(commonLabels["platform"],
h.Value/1000)
case model.MobileClientChannelSwitchDuration:
a.Metrics().ObserveMobileClientChannelSwitchDuration(commonLabels["platform"], h.Value/1000)
a.Metrics().ObserveMobileClientChannelSwitchDuration(commonLabels["platform"],
h.Value/1000)
case model.MobileClientTeamSwitchDuration:
a.Metrics().ObserveMobileClientTeamSwitchDuration(commonLabels["platform"], h.Value/1000)
a.Metrics().ObserveMobileClientTeamSwitchDuration(commonLabels["platform"],
h.Value/1000)
case model.DesktopClientCPUUsage:
a.Metrics().ObserveDesktopCpuUsage(commonLabels["platform"], commonLabels["desktop_app_version"], h.Labels["process"], h.Value)
case model.DesktopClientMemoryUsage:
+2 -2
View File
@@ -15,7 +15,7 @@ import (
func AssertLog(t *testing.T, logs io.Reader, level, message string) {
t.Helper()
if !hasMsg(t, logs, level, message) {
assert.Failf(t, "failed to find %s log message: %s", level, message)
assert.Failf(t, "failed to find", "Expected log_level: %s, log_message: %s", level, message)
}
}
@@ -23,7 +23,7 @@ func AssertLog(t *testing.T, logs io.Reader, level, message string) {
func AssertNoLog(t *testing.T, logs io.Reader, level, message string) {
t.Helper()
if hasMsg(t, logs, level, message) {
assert.Failf(t, "found %s log message: %s", level, message)
assert.Failf(t, "found", "Not expected log_level: %s log_message: %s", level, message)
}
}
+5 -5
View File
@@ -104,16 +104,16 @@ type MetricsInterface interface {
IncrementNotificationNotSentCounter(notificationType model.NotificationType, notSentReason model.NotificationReason, platform string)
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)
ObserveClientTimeToFirstByte(platform, agent, userID string, elapsed float64)
ObserveClientTimeToLastByte(platform, agent, userID string, elapsed float64)
ObserveClientTimeToDomInteractive(platform, agent, userID string, elapsed float64)
ObserveClientSplashScreenEnd(platform, agent, pageType, userID string, elapsed float64)
ObserveClientFirstContentfulPaint(platform, agent string, elapsed float64)
ObserveClientLargestContentfulPaint(platform, agent, region string, elapsed float64)
ObserveClientInteractionToNextPaint(platform, agent, interaction string, elapsed float64)
ObserveClientCumulativeLayoutShift(platform, agent string, elapsed float64)
IncrementClientLongTasks(platform, agent string, inc float64)
ObserveClientPageLoadDuration(platform, agent string, elapsed float64)
ObserveClientPageLoadDuration(platform, agent, userID string, elapsed float64)
ObserveClientChannelSwitchDuration(platform, agent, fresh string, elapsed float64)
ObserveClientTeamSwitchDuration(platform, agent, fresh string, elapsed float64)
ObserveClientRHSLoadDuration(platform, agent string, elapsed float64)
+15 -15
View File
@@ -328,9 +328,9 @@ func (_m *MetricsInterface) ObserveClientLargestContentfulPaint(platform string,
_m.Called(platform, agent, region, elapsed)
}
// ObserveClientPageLoadDuration provides a mock function with given fields: platform, agent, elapsed
func (_m *MetricsInterface) ObserveClientPageLoadDuration(platform string, agent string, elapsed float64) {
_m.Called(platform, agent, elapsed)
// ObserveClientPageLoadDuration provides a mock function with given fields: platform, agent, userID, elapsed
func (_m *MetricsInterface) ObserveClientPageLoadDuration(platform string, agent string, userID string, elapsed float64) {
_m.Called(platform, agent, userID, elapsed)
}
// ObserveClientRHSLoadDuration provides a mock function with given fields: platform, agent, elapsed
@@ -338,9 +338,9 @@ 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)
// ObserveClientSplashScreenEnd provides a mock function with given fields: platform, agent, pageType, userID, elapsed
func (_m *MetricsInterface) ObserveClientSplashScreenEnd(platform string, agent string, pageType string, userID string, elapsed float64) {
_m.Called(platform, agent, pageType, userID, elapsed)
}
// ObserveClientTeamSwitchDuration provides a mock function with given fields: platform, agent, fresh, elapsed
@@ -348,19 +348,19 @@ func (_m *MetricsInterface) ObserveClientTeamSwitchDuration(platform string, age
_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)
// ObserveClientTimeToDomInteractive provides a mock function with given fields: platform, agent, userID, elapsed
func (_m *MetricsInterface) ObserveClientTimeToDomInteractive(platform string, agent string, userID string, elapsed float64) {
_m.Called(platform, agent, userID, 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)
// ObserveClientTimeToFirstByte provides a mock function with given fields: platform, agent, userID, elapsed
func (_m *MetricsInterface) ObserveClientTimeToFirstByte(platform string, agent string, userID string, elapsed float64) {
_m.Called(platform, agent, userID, 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)
// ObserveClientTimeToLastByte provides a mock function with given fields: platform, agent, userID, elapsed
func (_m *MetricsInterface) ObserveClientTimeToLastByte(platform string, agent string, userID string, elapsed float64) {
_m.Called(platform, agent, userID, elapsed)
}
// ObserveClusterRequestDuration provides a mock function with given fields: elapsed
+76
View File
@@ -0,0 +1,76 @@
// Copyright (c) 2015-present Mattermost, Inc. All Rights Reserved.
// See LICENSE.enterprise for license information.
package metrics
import (
"github.com/prometheus/client_golang/prometheus"
"github.com/mattermost/mattermost/server/public/shared/mlog"
)
// HistogramVec is a wrapper of prometheus.HistogramVec that stores the buckets
// which are later passed down to WrappedObserver.
type HistogramVec struct {
*prometheus.HistogramVec
buckets []float64
fqName string
logger mlog.LoggerIFace
}
// WrappedObserver is a wrapper of prometheus.Observer which addtionally
// logs userIDs when the value exceeds or equals to the one in the highest bucket.
type WrappedObserver struct {
prometheus.Observer
labels prometheus.Labels
buckets []float64
logger mlog.LoggerIFace
metricName string
userID string
}
// NewHistogramVec returns a custom-purpose HistogramVec.
func NewHistogramVec(opts prometheus.HistogramOpts, labelNames []string, logger mlog.LoggerIFace) *HistogramVec {
if len(opts.Buckets) == 0 {
opts.Buckets = prometheus.DefBuckets
}
return &HistogramVec{
HistogramVec: prometheus.NewHistogramVec(opts, labelNames),
buckets: opts.Buckets,
fqName: prometheus.BuildFQName(opts.Namespace, opts.Subsystem, opts.Name),
logger: logger,
}
}
func (v *HistogramVec) With(labels prometheus.Labels, userID string) prometheus.Observer {
h, err := v.GetMetricWith(labels)
if err != nil {
panic(err)
}
return &WrappedObserver{
Observer: h,
labels: labels,
buckets: v.buckets,
logger: v.logger,
metricName: v.fqName,
userID: userID,
}
}
func (o *WrappedObserver) Observe(v float64) {
if v >= o.buckets[len(o.buckets)-1] {
fields := []mlog.Field{
mlog.String("metric_name", o.metricName),
mlog.String("user_id", o.userID),
mlog.Float("observed_value", v),
mlog.Float("highest_bucket_value", o.buckets[len(o.buckets)-1]),
}
for k, v := range o.labels {
fields = append(fields,
mlog.String("label_name", k),
mlog.String("label_value", v))
}
o.logger.Warn("Metric observation exceeded.", fields...)
}
o.Observer.Observe(v)
}
@@ -0,0 +1,35 @@
// Copyright (c) 2015-present Mattermost, Inc. All Rights Reserved.
// See LICENSE.enterprise for license information.
package metrics
import (
"testing"
"github.com/prometheus/client_golang/prometheus"
"github.com/stretchr/testify/require"
"github.com/mattermost/mattermost/server/public/shared/mlog"
"github.com/mattermost/mattermost/server/v8/channels/api4"
"github.com/mattermost/mattermost/server/v8/channels/testlib"
)
func TestWrappedObserver(t *testing.T) {
th := api4.Setup(t)
defer th.TearDown()
h := NewHistogramVec(prometheus.HistogramOpts{
Namespace: MetricsNamespace,
Subsystem: MetricsSubsystemClientsWeb,
Name: "test",
Buckets: []float64{0, 5, 10},
}, []string{"l1"}, th.TestLogger)
h.With(prometheus.Labels{"l1": "hello"}, th.BasicUser.Id).Observe(6)
require.NoError(t, th.TestLogger.Flush())
testlib.AssertNoLog(t, th.LogBuffer, mlog.LvlWarn.Name, "Metric observation exceeded.")
h.With(prometheus.Labels{"l1": "hello"}, th.BasicUser.Id).Observe(10)
require.NoError(t, th.TestLogger.Flush())
testlib.AssertLog(t, th.LogBuffer, mlog.LvlWarn.Name, "Metric observation exceeded.")
}
+31 -21
View File
@@ -201,16 +201,16 @@ type MetricsInterfaceImpl struct {
NotificationNotSentCounters *prometheus.CounterVec
NotificationUnsupportedCounters *prometheus.CounterVec
ClientTimeToFirstByte *prometheus.HistogramVec
ClientTimeToLastByte *prometheus.HistogramVec
ClientTimeToDOMInteractive *prometheus.HistogramVec
ClientSplashScreenEnd *prometheus.HistogramVec
ClientTimeToFirstByte *HistogramVec
ClientTimeToLastByte *HistogramVec
ClientTimeToDOMInteractive *HistogramVec
ClientSplashScreenEnd *HistogramVec
ClientFirstContentfulPaint *prometheus.HistogramVec
ClientLargestContentfulPaint *prometheus.HistogramVec
ClientInteractionToNextPaint *prometheus.HistogramVec
ClientCumulativeLayoutShift *prometheus.HistogramVec
ClientLongTasks *prometheus.CounterVec
ClientPageLoadDuration *prometheus.HistogramVec
ClientPageLoadDuration *HistogramVec
ClientChannelSwitchDuration *prometheus.HistogramVec
ClientTeamSwitchDuration *prometheus.HistogramVec
ClientRHSLoadDuration *prometheus.HistogramVec
@@ -1179,7 +1179,7 @@ func New(ps *platform.PlatformService, driver, dataSource string) *MetricsInterf
)
m.Registry.MustRegister(m.NotificationUnsupportedCounters)
m.ClientTimeToFirstByte = prometheus.NewHistogramVec(
m.ClientTimeToFirstByte = NewHistogramVec(
prometheus.HistogramOpts{
Namespace: MetricsNamespace,
Subsystem: MetricsSubsystemClientsWeb,
@@ -1187,10 +1187,11 @@ func New(ps *platform.PlatformService, driver, dataSource string) *MetricsInterf
Help: "Duration from when a browser starts to request a page from a server until when it starts to receive data in response (seconds)",
},
[]string{"platform", "agent"},
m.Platform.Log(),
)
m.Registry.MustRegister(m.ClientTimeToFirstByte)
m.ClientTimeToLastByte = prometheus.NewHistogramVec(
m.ClientTimeToLastByte = NewHistogramVec(
prometheus.HistogramOpts{
Namespace: MetricsNamespace,
Subsystem: MetricsSubsystemClientsWeb,
@@ -1198,28 +1199,33 @@ func New(ps *platform.PlatformService, driver, dataSource string) *MetricsInterf
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.Platform.Log(),
)
m.Registry.MustRegister(m.ClientTimeToLastByte)
m.ClientTimeToDOMInteractive = prometheus.NewHistogramVec(
m.ClientTimeToDOMInteractive = 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)",
Buckets: []float64{.1, .25, .5, 1, 2.5, 5, 7.5, 10, 12.5, 15},
},
[]string{"platform", "agent"},
m.Platform.Log(),
)
m.Registry.MustRegister(m.ClientTimeToDOMInteractive)
m.ClientSplashScreenEnd = prometheus.NewHistogramVec(
m.ClientSplashScreenEnd = 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)",
Buckets: []float64{.1, .25, .5, 1, 2.5, 5, 7.5, 10, 12.5, 15},
},
[]string{"platform", "agent", "page_type"},
m.Platform.Log(),
)
m.Registry.MustRegister(m.ClientSplashScreenEnd)
@@ -1284,7 +1290,7 @@ func New(ps *platform.PlatformService, driver, dataSource string) *MetricsInterf
)
m.Registry.MustRegister(m.ClientLongTasks)
m.ClientPageLoadDuration = prometheus.NewHistogramVec(
m.ClientPageLoadDuration = NewHistogramVec(
prometheus.HistogramOpts{
Namespace: MetricsNamespace,
Subsystem: MetricsSubsystemClientsWeb,
@@ -1293,6 +1299,7 @@ func New(ps *platform.PlatformService, driver, dataSource string) *MetricsInterf
Buckets: []float64{.005, .01, .025, .05, .1, .25, .5, 1, 2.5, 5, 10, 20, 40},
},
[]string{"platform", "agent"},
m.Platform.Log(),
)
m.Registry.MustRegister(m.ClientPageLoadDuration)
@@ -1870,20 +1877,20 @@ func (mi *MetricsInterfaceImpl) DecrementHTTPWebSockets(originClient string) {
mi.HTTPWebsocketsGauge.With(prometheus.Labels{"origin_client": originClient}).Dec()
}
func (mi *MetricsInterfaceImpl) ObserveClientTimeToFirstByte(platform, agent string, elapsed float64) {
mi.ClientTimeToFirstByte.With(prometheus.Labels{"platform": platform, "agent": agent}).Observe(elapsed)
func (mi *MetricsInterfaceImpl) ObserveClientTimeToFirstByte(platform, agent, userID string, elapsed float64) {
mi.ClientTimeToFirstByte.With(prometheus.Labels{"platform": platform, "agent": agent}, userID).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) ObserveClientTimeToLastByte(platform, agent, userID string, elapsed float64) {
mi.ClientTimeToLastByte.With(prometheus.Labels{"platform": platform, "agent": agent}, userID).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) ObserveClientTimeToDomInteractive(platform, agent, userID string, elapsed float64) {
mi.ClientTimeToDOMInteractive.With(prometheus.Labels{"platform": platform, "agent": agent}, userID).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) ObserveClientSplashScreenEnd(platform, agent, pageType, userID string, elapsed float64) {
mi.ClientSplashScreenEnd.With(prometheus.Labels{"platform": platform, "agent": agent, "page_type": pageType}, userID).Observe(elapsed)
}
func (mi *MetricsInterfaceImpl) ObserveClientFirstContentfulPaint(platform, agent string, elapsed float64) {
@@ -1906,8 +1913,11 @@ func (mi *MetricsInterfaceImpl) IncrementClientLongTasks(platform, agent string,
mi.ClientLongTasks.With(prometheus.Labels{"platform": platform, "agent": agent}).Add(inc)
}
func (mi *MetricsInterfaceImpl) ObserveClientPageLoadDuration(platform, agent string, elapsed float64) {
mi.ClientPageLoadDuration.With(prometheus.Labels{"platform": platform, "agent": agent}).Observe(elapsed)
func (mi *MetricsInterfaceImpl) ObserveClientPageLoadDuration(platform, agent, userID string, elapsed float64) {
mi.ClientPageLoadDuration.With(prometheus.Labels{
"platform": platform,
"agent": agent,
}, userID).Observe(elapsed)
}
func (mi *MetricsInterfaceImpl) ObserveClientChannelSwitchDuration(platform, agent, fresh string, elapsed float64) {
@@ -1946,7 +1956,7 @@ func (mi *MetricsInterfaceImpl) ObserveMobileClientTeamSwitchDuration(platform s
mi.MobileClientTeamSwitchDuration.With(prometheus.Labels{"platform": platform}).Observe(elapsed)
}
func (mi *MetricsInterfaceImpl) ObserveMobileClientSessionMetadata(version string, platform string, value float64, notificationDisabled string) {
func (mi *MetricsInterfaceImpl) ObserveMobileClientSessionMetadata(version, platform string, value float64, notificationDisabled string) {
mi.MobileClientSessionMetadataGauge.With(prometheus.Labels{"version": version, "platform": platform, "notifications_disabled": notificationDisabled}).Set(value)
}