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 <kisunji92@gmail.com>

* 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 <kisunji92@gmail.com>
This commit is contained in:
Gabriel Santos 2022-09-15 18:04:37 +01:00 committed by GitHub
parent 13ac6356a8
commit 09c00ff39a
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
4 changed files with 31 additions and 5 deletions

3
.changelog/12905.txt Normal file
View File

@ -0,0 +1,3 @@
```release-note:improvement
metrics: Service RPC calls less than 1ms are now emitted as a decimal number.
```

View File

@ -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"} // 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) { func assertMetricExistsWithLabels(t *testing.T, respRec *httptest.ResponseRecorder, metric string, labelNames []string) {
if respRec.Body.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) { func assertMetricNotExists(t *testing.T, respRec *httptest.ResponseRecorder, metric string) {
if respRec.Body.String() == "" { if respRec.Body.String() == "" {
t.Fatalf("Response body is empty.") 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"}) 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 // 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) 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")
}) })
} }

View File

@ -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) { 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) reqType := requestType(request)
isLeader := r.getServerLeadership() isLeader := r.getServerLeadership()
@ -64,7 +65,7 @@ func (r *RequestRecorder) Record(requestName string, rpcType string, start time.
labels = r.addOptionalLabels(request, labels) labels = r.addOptionalLabels(request, labels)
// math.MaxInt64 < math.MaxFloat32 is true so we should be good! // 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) labelsArr := flattenLabels(labels)
r.Logger.Trace(requestLogName, labelsArr...) r.Logger.Trace(requestLogName, labelsArr...)

View File

@ -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 | | `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 ### Labels
The the server workload metrics above come with the following labels: The the server workload metrics above come with the following labels: