From e53af28bd7a941caa76e40922aaf6e8b40e479f7 Mon Sep 17 00:00:00 2001 From: Gabriel Santos Date: Thu, 15 Sep 2022 18:04:37 +0100 Subject: [PATCH] Middleware: `RequestRecorder` reports calls below 1ms as decimal value (#12905) * Typos * Test failing * Convert values <1ms to decimal * Fix test * Update docs and test error msg * Applied suggested changes to test case * Changelog file and suggested changes * Update .changelog/12905.txt Co-authored-by: Chris S. Kim * suggested change - start duration with microseconds instead of nanoseconds * fix error * suggested change - floats Co-authored-by: alex <8968914+acpana@users.noreply.github.com> Co-authored-by: Chris S. Kim --- .changelog/12905.txt | 3 +++ agent/metrics_test.go | 26 +++++++++++++++++++++++- agent/rpc/middleware/interceptors.go | 5 +++-- website/content/docs/agent/telemetry.mdx | 2 -- 4 files changed, 31 insertions(+), 5 deletions(-) create mode 100644 .changelog/12905.txt diff --git a/.changelog/12905.txt b/.changelog/12905.txt new file mode 100644 index 0000000000..7b2889f245 --- /dev/null +++ b/.changelog/12905.txt @@ -0,0 +1,3 @@ +```release-note:improvement +metrics: Service RPC calls less than 1ms are now emitted as a decimal number. +``` diff --git a/agent/metrics_test.go b/agent/metrics_test.go index fde4047130..4b80f9edaf 100644 --- a/agent/metrics_test.go +++ b/agent/metrics_test.go @@ -47,7 +47,7 @@ func assertMetricExists(t *testing.T, respRec *httptest.ResponseRecorder, metric } } -// assertMetricExistsWithLabels looks in the prometheus metrics reponse for the metric name and all the labels. eg: +// assertMetricExistsWithLabels looks in the prometheus metrics response for the metric name and all the labels. eg: // new_rpc_metrics_rpc_server_call{errored="false",method="Status.Ping",request_type="unknown",rpc_type="net/rpc"} func assertMetricExistsWithLabels(t *testing.T, respRec *httptest.ResponseRecorder, metric string, labelNames []string) { if respRec.Body.String() == "" { @@ -136,6 +136,28 @@ func assertMetricExistsWithValue(t *testing.T, respRec *httptest.ResponseRecorde } } +func assertMetricsWithLabelIsNonZero(t *testing.T, respRec *httptest.ResponseRecorder, label, labelValue string) { + if respRec.Body.String() == "" { + t.Fatalf("Response body is empty.") + } + + metrics := respRec.Body.String() + labelWithValueTarget := label + "=" + "\"" + labelValue + "\"" + + for _, line := range strings.Split(metrics, "\n") { + if len(line) < 1 || line[0] == '#' { + continue + } + + if strings.Contains(line, labelWithValueTarget) { + s := strings.SplitN(line, " ", 2) + if s[1] == "0" { + t.Fatalf("Metric with label provided \"%s:%s\" has the value 0", label, labelValue) + } + } + } +} + func assertMetricNotExists(t *testing.T, respRec *httptest.ResponseRecorder, metric string) { if respRec.Body.String() == "" { t.Fatalf("Response body is empty.") @@ -205,6 +227,8 @@ func TestAgent_OneTwelveRPCMetrics(t *testing.T) { assertMetricExistsWithLabels(t, respRec, metricsPrefix+"_rpc_server_call", []string{"errored", "method", "request_type", "rpc_type", "leader"}) // make sure we see 3 Status.Ping metrics corresponding to the calls we made above assertLabelWithValueForMetricExistsNTime(t, respRec, metricsPrefix+"_rpc_server_call", "method", "Status.Ping", 3) + // make sure rpc calls with elapsed time below 1ms are reported as decimal + assertMetricsWithLabelIsNonZero(t, respRec, "method", "Status.Ping") }) } diff --git a/agent/rpc/middleware/interceptors.go b/agent/rpc/middleware/interceptors.go index 049283ac20..6abcf0a443 100644 --- a/agent/rpc/middleware/interceptors.go +++ b/agent/rpc/middleware/interceptors.go @@ -49,7 +49,8 @@ func NewRequestRecorder(logger hclog.Logger, isLeader func() bool, localDC strin } func (r *RequestRecorder) Record(requestName string, rpcType string, start time.Time, request interface{}, respErrored bool) { - elapsed := time.Since(start).Milliseconds() + elapsed := time.Since(start).Microseconds() + elapsedMs := float32(elapsed) / 1000 reqType := requestType(request) isLeader := r.getServerLeadership() @@ -64,7 +65,7 @@ func (r *RequestRecorder) Record(requestName string, rpcType string, start time. labels = r.addOptionalLabels(request, labels) // math.MaxInt64 < math.MaxFloat32 is true so we should be good! - r.RecorderFunc(metricRPCRequest, float32(elapsed), labels) + r.RecorderFunc(metricRPCRequest, elapsedMs, labels) labelsArr := flattenLabels(labels) r.Logger.Trace(requestLogName, labelsArr...) diff --git a/website/content/docs/agent/telemetry.mdx b/website/content/docs/agent/telemetry.mdx index 3926ada342..21654025e9 100644 --- a/website/content/docs/agent/telemetry.mdx +++ b/website/content/docs/agent/telemetry.mdx @@ -557,8 +557,6 @@ Label based RPC metrics were added in Consul 1.12.0 as a Beta feature to better | ------------------------------------- | --------------------------------------------------------- | ------ | --------- | | `consul.rpc.server.call` | Measures the elapsed time taken to complete an RPC call. | ms | summary | -Note that values of the `consul.rpc.server.call` may emit as `0 ms`. That means that the elapsed time < `1 ms`. - ### Labels The the server workload metrics above come with the following labels: