-
Notifications
You must be signed in to change notification settings - Fork 142
rpc: report psrpc request delivery, expiry and claim outcomes #1687
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: main
Are you sure you want to change the base?
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.
Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.
Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.
Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.
Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.
Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -23,6 +23,7 @@ import ( | |
| "go.uber.org/atomic" | ||
| "golang.org/x/exp/maps" | ||
|
|
||
| "github.com/livekit/protocol/logger" | ||
| "github.com/livekit/psrpc" | ||
| "github.com/livekit/psrpc/pkg/middleware" | ||
| ) | ||
|
|
@@ -38,6 +39,10 @@ type psrpcMetrics struct { | |
| streamCurrent *prometheus.GaugeVec | ||
| errorTotal *prometheus.CounterVec | ||
| bytesTotal *prometheus.CounterVec | ||
| requestsReceived *prometheus.CounterVec | ||
| requestsExpired *prometheus.CounterVec | ||
| claimTotal *prometheus.CounterVec | ||
| claimWaitTime prometheus.ObserverVec | ||
| } | ||
|
|
||
| var ( | ||
|
|
@@ -84,6 +89,9 @@ func InitPSRPCStats(constLabels prometheus.Labels, opts ...PSRPCMetricsOption) { | |
| labels := append(curryLabelNames, "role", "kind", "service", "method") | ||
| streamLabels := append(curryLabelNames, "role", "service", "method") | ||
| bytesLabels := append(labels, "direction") | ||
| // Lifecycle metrics are server-side only, so they carry no role label. | ||
| lifecycleLabels := append(curryLabelNames, "service", "method") | ||
| claimLabels := append(lifecycleLabels, "outcome") | ||
|
|
||
| metricsBase.requestTime = prometheus.NewHistogramVec(prometheus.HistogramOpts{ | ||
| Namespace: livekitNamespace, | ||
|
|
@@ -124,6 +132,34 @@ func InitPSRPCStats(constLabels prometheus.Labels, opts ...PSRPCMetricsOption) { | |
| ConstLabels: constLabels, | ||
| }, bytesLabels) | ||
|
|
||
| metricsBase.requestsReceived = prometheus.NewCounterVec(prometheus.CounterOpts{ | ||
| Namespace: livekitNamespace, | ||
| Subsystem: "psrpc", | ||
| Name: "requests_received_total", | ||
| ConstLabels: constLabels, | ||
| }, lifecycleLabels) | ||
| metricsBase.requestsExpired = prometheus.NewCounterVec(prometheus.CounterOpts{ | ||
| Namespace: livekitNamespace, | ||
| Subsystem: "psrpc", | ||
| Name: "requests_expired_total", | ||
| ConstLabels: constLabels, | ||
| }, lifecycleLabels) | ||
| metricsBase.claimTotal = prometheus.NewCounterVec(prometheus.CounterOpts{ | ||
| Namespace: livekitNamespace, | ||
| Subsystem: "psrpc", | ||
| Name: "claim_total", | ||
| ConstLabels: constLabels, | ||
| }, claimLabels) | ||
| metricsBase.claimWaitTime = prometheus.NewHistogramVec(prometheus.HistogramOpts{ | ||
| Namespace: livekitNamespace, | ||
| Subsystem: "psrpc", | ||
| Name: "claim_wait_time_ms", | ||
| ConstLabels: constLabels, | ||
| // A granted claim settles in single-digit ms; a timed-out one runs to | ||
| // the caller's selection timeout, 1s by default. | ||
| Buckets: []float64{1, 5, 10, 25, 50, 100, 250, 500, 1000, 3000}, | ||
| }, claimLabels) | ||
|
|
||
| metricsBase.mu.Unlock() | ||
|
|
||
| prometheus.MustRegister(metricsBase.requestTime) | ||
|
|
@@ -132,6 +168,10 @@ func InitPSRPCStats(constLabels prometheus.Labels, opts ...PSRPCMetricsOption) { | |
| prometheus.MustRegister(metricsBase.streamCurrent) | ||
| prometheus.MustRegister(metricsBase.errorTotal) | ||
| prometheus.MustRegister(metricsBase.bytesTotal) | ||
| prometheus.MustRegister(metricsBase.requestsReceived) | ||
| prometheus.MustRegister(metricsBase.requestsExpired) | ||
| prometheus.MustRegister(metricsBase.claimTotal) | ||
| prometheus.MustRegister(metricsBase.claimWaitTime) | ||
|
|
||
| CurryMetricLabels(o.curryLabels) | ||
| } | ||
|
|
@@ -156,10 +196,17 @@ func CurryMetricLabels(labels prometheus.Labels) { | |
| streamCurrent: metricsBase.streamCurrent.MustCurryWith(metricsBase.curryLabels), | ||
| errorTotal: metricsBase.errorTotal.MustCurryWith(metricsBase.curryLabels), | ||
| bytesTotal: metricsBase.bytesTotal.MustCurryWith(metricsBase.curryLabels), | ||
| requestsReceived: metricsBase.requestsReceived.MustCurryWith(metricsBase.curryLabels), | ||
| requestsExpired: metricsBase.requestsExpired.MustCurryWith(metricsBase.curryLabels), | ||
| claimTotal: metricsBase.claimTotal.MustCurryWith(metricsBase.curryLabels), | ||
| claimWaitTime: metricsBase.claimWaitTime.MustCurryWith(metricsBase.curryLabels), | ||
| }) | ||
| } | ||
|
|
||
| var _ middleware.MetricsObserver = PSRPCMetricsObserver{} | ||
| var ( | ||
| _ middleware.MetricsObserver = PSRPCMetricsObserver{} | ||
| _ psrpc.RequestObserver = PSRPCMetricsObserver{} | ||
| ) | ||
|
|
||
| type PSRPCMetricsObserver struct{} | ||
|
|
||
|
|
@@ -235,3 +282,32 @@ func (o UnimplementedMetricsObserver) OnStreamOpen(role middleware.MetricRole, r | |
| } | ||
| func (o UnimplementedMetricsObserver) OnStreamClose(role middleware.MetricRole, rpcInfo psrpc.RPCInfo) { | ||
| } | ||
|
|
||
| // OnRequestReceived, OnRequestExpired and OnClaim report server-side lifecycle | ||
| // events that the interceptor chain cannot see, because in each case the | ||
| // handler is never invoked. Installed by psrpc.WithServerObserver, which is | ||
| // separate from middleware.WithServerMetrics. | ||
|
|
||
| func (o PSRPCMetricsObserver) OnRequestReceived(info psrpc.RPCInfo) { | ||
| metrics.Load().requestsReceived.WithLabelValues(info.Service, info.Method).Inc() | ||
| } | ||
|
|
||
| func (o PSRPCMetricsObserver) OnRequestExpired(info psrpc.RPCInfo, lateBy time.Duration) { | ||
| metrics.Load().requestsExpired.WithLabelValues(info.Service, info.Method).Inc() | ||
| logger.Warnw("psrpc request dropped: expired before dispatch", nil, | ||
| "service", info.Service, "method", info.Method, "lateBy", lateBy) | ||
| } | ||
|
|
||
| func (o PSRPCMetricsObserver) OnClaim(info psrpc.RPCInfo, outcome psrpc.ClaimOutcome, wait time.Duration) { | ||
| m := metrics.Load() | ||
| m.claimTotal.WithLabelValues(info.Service, info.Method, outcome.String()).Inc() | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. the histogram will have a |
||
| m.claimWaitTime.WithLabelValues(info.Service, info.Method, outcome.String()).Observe(float64(wait.Milliseconds())) | ||
|
|
||
| if outcome == psrpc.ClaimTimedOut { | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. same here |
||
| // The caller stopped waiting for a bid before ours was accepted. It has | ||
| // already returned ErrNoResponse upstream, so without this line the | ||
| // request leaves no record on either side. | ||
| logger.Warnw("psrpc claim timed out before the caller granted it", nil, | ||
| "service", info.Service, "method", info.Method, "waited", wait) | ||
| } | ||
| } | ||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,137 @@ | ||
| // Copyright 2023 LiveKit, Inc. | ||
| // | ||
| // Licensed under the Apache License, Version 2.0 (the "License"); | ||
| // you may not use this file except in compliance with the License. | ||
| // You may obtain a copy of the License at | ||
| // | ||
| // http://www.apache.org/licenses/LICENSE-2.0 | ||
| // | ||
| // Unless required by applicable law or agreed to in writing, software | ||
| // distributed under the License is distributed on an "AS IS" BASIS, | ||
| // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. | ||
| // See the License for the specific language governing permissions and | ||
| // limitations under the License. | ||
|
|
||
| package rpc | ||
|
|
||
| import ( | ||
| "errors" | ||
| "strings" | ||
| "testing" | ||
| "time" | ||
|
|
||
| "github.com/prometheus/client_golang/prometheus" | ||
| "github.com/stretchr/testify/require" | ||
|
|
||
| "github.com/livekit/psrpc" | ||
| "github.com/livekit/psrpc/pkg/middleware" | ||
| ) | ||
|
|
||
| // TestRequestObserverMetrics asserts the server-side lifecycle events register | ||
| // and emit. These are the only signals available for a request whose handler is | ||
| // never invoked, so a silent regression here would be invisible in production. | ||
| func TestRequestObserverMetrics(t *testing.T) { | ||
| InitPSRPCStats(prometheus.Labels{}) | ||
| o := PSRPCMetricsObserver{} | ||
| info := psrpc.RPCInfo{Service: "LifecycleSvc", Method: "TestMethod"} | ||
|
|
||
| o.OnRequestReceived(info) | ||
| o.OnRequestExpired(info, 20*time.Millisecond) | ||
| o.OnClaim(info, psrpc.ClaimGranted, 3*time.Millisecond) | ||
| o.OnClaim(info, psrpc.ClaimTimedOut, 1005*time.Millisecond) | ||
|
|
||
| got := gatherPSRPCSeries(t, "LifecycleSvc") | ||
| require.Equal(t, 1.0, got["livekit_psrpc_requests_received_total"]) | ||
| require.Equal(t, 1.0, got["livekit_psrpc_requests_expired_total"]) | ||
| require.Equal(t, 1.0, got["livekit_psrpc_claim_total|granted"]) | ||
| require.Equal(t, 1.0, got["livekit_psrpc_claim_total|timed_out"]) | ||
| require.Equal(t, 1.0, got["livekit_psrpc_claim_wait_time_ms|granted"]) | ||
| require.Equal(t, 1.0, got["livekit_psrpc_claim_wait_time_ms|timed_out"]) | ||
| } | ||
|
|
||
| // TestMetricsObserverMetrics covers the interceptor-driven series. Each method | ||
| // routes to a different metric depending on whether the call errored, so the | ||
| // error and success paths are asserted separately. | ||
| func TestMetricsObserverMetrics(t *testing.T) { | ||
| InitPSRPCStats(prometheus.Labels{}) | ||
| o := PSRPCMetricsObserver{} | ||
| info := psrpc.RPCInfo{Service: "ObserverSvc", Method: "TestMethod"} | ||
| boom := errors.New("boom") | ||
|
|
||
| o.OnUnaryRequest(middleware.ClientRole, info, 5*time.Millisecond, nil, 10, 20) | ||
| o.OnUnaryRequest(middleware.ClientRole, info, 5*time.Millisecond, boom, 1, 2) | ||
| o.OnMultiRequest(middleware.ServerRole, info, 7*time.Millisecond, 2, 0, 30, 40) | ||
| o.OnMultiRequest(middleware.ServerRole, info, 7*time.Millisecond, 0, 1, 0, 0) | ||
| o.OnStreamSend(middleware.ClientRole, info, 3*time.Millisecond, nil, 50) | ||
| o.OnStreamRecv(middleware.ClientRole, info, nil, 60) | ||
| o.OnStreamOpen(middleware.ServerRole, info) | ||
| o.OnStreamOpen(middleware.ServerRole, info) | ||
| o.OnStreamClose(middleware.ServerRole, info) | ||
|
|
||
| got := gatherPSRPCSeries(t, "ObserverSvc") | ||
|
|
||
| require.Equal(t, 1.0, got["livekit_psrpc_request_time_ms|client|rpc"]) | ||
| require.Equal(t, 1.0, got["livekit_psrpc_error_total|client|rpc"]) | ||
| require.Equal(t, 1.0, got["livekit_psrpc_request_time_ms|server|multirpc"]) | ||
| require.Equal(t, 1.0, got["livekit_psrpc_error_total|server|multirpc"]) | ||
| require.Equal(t, 1.0, got["livekit_psrpc_stream_send_time_ms|client"]) | ||
| require.Equal(t, 1.0, got["livekit_psrpc_stream_receive_total|client"]) | ||
|
|
||
| // stream_count is a gauge: two opens and one close leave one stream live. | ||
| require.Equal(t, 1.0, got["livekit_psrpc_stream_count|server"]) | ||
|
|
||
| require.Equal(t, 11.0, got["livekit_psrpc_bytes_total|client|rpc|rx"]) | ||
| require.Equal(t, 22.0, got["livekit_psrpc_bytes_total|client|rpc|tx"]) | ||
| require.Equal(t, 30.0, got["livekit_psrpc_bytes_total|server|multirpc|rx"]) | ||
| require.Equal(t, 40.0, got["livekit_psrpc_bytes_total|server|multirpc|tx"]) | ||
| require.Equal(t, 60.0, got["livekit_psrpc_bytes_total|client|stream|rx"]) | ||
| require.Equal(t, 50.0, got["livekit_psrpc_bytes_total|client|stream|tx"]) | ||
| } | ||
|
|
||
| // discriminatingLabels are appended to each key in the order listed, so a key | ||
| // reads livekit_psrpc_bytes_total|client|rpc|rx. | ||
| var discriminatingLabels = []string{"role", "kind", "direction", "outcome"} | ||
|
|
||
| // gatherPSRPCSeries returns livekit_psrpc_* values for one service: counter and | ||
| // gauge values, and sample counts for histograms. Filtering on service keeps | ||
| // tests in this package independent — the registry is global and accumulates | ||
| // across them, so a shared key would make assertions order-dependent. | ||
| func gatherPSRPCSeries(t *testing.T, service string) map[string]float64 { | ||
| t.Helper() | ||
| mfs, err := prometheus.DefaultGatherer.Gather() | ||
| require.NoError(t, err) | ||
|
|
||
| out := map[string]float64{} | ||
| for _, mf := range mfs { | ||
| if !strings.HasPrefix(mf.GetName(), "livekit_psrpc_") { | ||
| continue | ||
| } | ||
| for _, m := range mf.GetMetric() { | ||
| labels := map[string]string{} | ||
| for _, l := range m.GetLabel() { | ||
| labels[l.GetName()] = l.GetValue() | ||
| } | ||
| if labels["service"] != service { | ||
| continue | ||
| } | ||
|
|
||
| key := mf.GetName() | ||
| for _, name := range discriminatingLabels { | ||
| if v, ok := labels[name]; ok { | ||
| key += "|" + v | ||
| } | ||
| } | ||
|
|
||
| if c := m.GetCounter(); c != nil { | ||
| out[key] += c.GetValue() | ||
| } | ||
| if g := m.GetGauge(); g != nil { | ||
| out[key] += g.GetValue() | ||
| } | ||
| if h := m.GetHistogram(); h != nil { | ||
| out[key] += float64(h.GetSampleCount()) | ||
| } | ||
| } | ||
| } | ||
| return out | ||
| } |
Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.
Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.
Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.
Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.
Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.
Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
the metric captures most of the same information - let's skip logging here.