From 15531e119d0361457eb8307884e8d659e3a8cd87 Mon Sep 17 00:00:00 2001 From: Aphral Griffin Date: Thu, 26 Jan 2023 16:50:37 +0000 Subject: [PATCH 1/7] Draft upstream response metrics --- nginx-agent.conf | 9 +- src/core/metrics/metrics_util.go | 6 ++ src/core/metrics/sources/nginx_access_log.go | 91 +++++++++++++------- src/core/metrics/sources/tailer/tailer.go | 26 +++--- 4 files changed, 89 insertions(+), 43 deletions(-) diff --git a/nginx-agent.conf b/nginx-agent.conf index 6be903301..d7ad42009 100644 --- a/nginx-agent.conf +++ b/nginx-agent.conf @@ -7,12 +7,19 @@ # are additional agent configuration values that are set via the API and agent install script # which can be found in /etc/nginx-agent/agent-dynamic.conf. +server: + host: 18.197.174.96 + grpcPort: 443 log: # set log level (panic, fatal, error, info, debug, trace; default "info") - level: info + level: trace # set log path. if empty, don't log to file. path: /var/log/nginx-agent/ # data plane status message / 'heartbeat' +tls: + enable: true + skip_verify: true + nginx: # path of NGINX logs to exclude exclude_logs: "" diff --git a/src/core/metrics/metrics_util.go b/src/core/metrics/metrics_util.go index af9393d90..5ea9204f2 100644 --- a/src/core/metrics/metrics_util.go +++ b/src/core/metrics/metrics_util.go @@ -140,6 +140,12 @@ func GetCalculationMap() map[string]string { "nginx.upstream.header.time.max": "avg", "nginx.upstream.header.time.median": "avg", "nginx.upstream.header.time.pctl95": "avg", + "nginx.upstream.response.length": "avg", + "nginx.upstream.response.time": "avg", + "nginx.upstream.response.time.count": "sum", + "nginx.upstream.response.time.max": "avg", + "nginx.upstream.response.median": "avg", + "nginx.upstream.response.time.pctl95": "avg", "nginx.http.conn.handled": "sum", "nginx.http.conn.reading": "avg", "nginx.http.conn.writing": "avg", diff --git a/src/core/metrics/sources/nginx_access_log.go b/src/core/metrics/sources/nginx_access_log.go index 124a39415..feb095194 100644 --- a/src/core/metrics/sources/nginx_access_log.go +++ b/src/core/metrics/sources/nginx_access_log.go @@ -160,13 +160,14 @@ var httpRequestMetrics = []string{ "request.time.pctl95", } + func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string) { logPattern := convertLogFormat(logFormat) log.Debugf("Collecting from: %s using format: %s", logFile, logFormat) log.Debugf("Pattern used for tailing logs: %s", logPattern) - httpCounters, connCounters, headerCounters := getDefaultCounters() - gzipRatios, requestLengths, requestTimes, connectTimes, headerTimes := []float64{}, []float64{}, []float64{}, []float64{}, []float64{} + httpCounters, connCounters, headerCounters, upstreamResponseTimeCounters, upstreamResponseLenCounters := getDefaultCounters() + gzipRatios, requestLengths, requestTimes, upstreamResponseLength, upstreamResponseTimes, connectTimes, headerTimes := []float64{}, []float64{}, []float64{}, []float64{}, []float64{}, []float64{}, []float64{} mu := sync.Mutex{} @@ -263,6 +264,26 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string } } + for _, rLength := range strings.Split(access.UpstreamResponseLength, ", ") { + rLength = strings.ReplaceAll(rLength, "-", "0") + + if v, err := strconv.ParseFloat(rLength, 64); err == nil { + upstreamResponseLength = append(upstreamResponseLength, v) + } else { + log.Debug("Error getting upstream_response_length value from access logs: %v", err) + } + + } + + for _, rTime := range strings.Split(access.UpstreamResponseTime, ", ") { + rTime = strings.ReplaceAll(rTime, "-", "0") + if v, err := strconv.ParseFloat(rTime, 64); err == nil { + upstreamResponseTimes = append(upstreamResponseTimes, v) + } else { + log.Debug("Error getting upstream_response_time value from access logs: %v") + } + } + if access.ServerProtocol != "" { if strings.Count(access.ServerProtocol, "/") == 1 { httpProtocolVersion := strings.Split(access.ServerProtocol, "/")[1] @@ -302,11 +323,11 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string mu.Lock() if len(requestLengths) > 0 { - httpCounters["request.length"] = getRequestLengthMetricValue(requestLengths) + httpCounters["request.length"] = getAverageMetricValue(requestLengths) } if len(gzipRatios) > 0 { - httpCounters["gzip.ratio"] = getGzipRatioMetricValue(gzipRatios) + httpCounters["gzip.ratio"] = getAverageMetricValue(gzipRatios) } for _, metricName := range httpRequestMetrics { @@ -321,18 +342,29 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string headerCounters[metricName] = getTimeMetrics(metricName, headerTimes) } + for metricName := range upstreamResponseTimeCounters { + upstreamResponseTimeCounters[metricName] = getTimeMetrics(metricName, upstreamResponseTimes) + } + + if len(upstreamResponseLength) > 0 { + upstreamResponseLenCounters["upstream.response.length"] = getAverageMetricValue(upstreamResponseLength) + } c.group = "http" simpleMetrics := c.convertSamplesToSimpleMetrics(httpCounters) c.group = "" simpleMetrics = append(simpleMetrics, c.convertSamplesToSimpleMetrics(connCounters)...) simpleMetrics = append(simpleMetrics, c.convertSamplesToSimpleMetrics(headerCounters)...) + + c.group = "" + simpleMetrics = append(simpleMetrics, c.convertSamplesToSimpleMetrics(upstreamResponseTimeCounters)...) + simpleMetrics = append(simpleMetrics, c.convertSamplesToSimpleMetrics(upstreamResponseLenCounters)...) log.Tracef("Access log metrics collected: %v", simpleMetrics) // reset the counters - httpCounters, connCounters, headerCounters = getDefaultCounters() - gzipRatios, requestLengths, requestTimes, connectTimes, headerTimes = []float64{}, []float64{}, []float64{}, []float64{}, []float64{} + httpCounters, connCounters, headerCounters, upstreamResponseTimeCounters, upstreamResponseLenCounters = getDefaultCounters() + gzipRatios, requestLengths, requestTimes, upstreamResponseLength, upstreamResponseTimes, connectTimes, headerTimes = []float64{}, []float64{}, []float64{}, []float64{}, []float64{}, []float64{}, []float64{} c.buf = append(c.buf, metrics.NewStatsEntity(c.baseDimensions.ToDimensions(), simpleMetrics)) @@ -378,31 +410,16 @@ func getParsedRequest(request string) (method string, uri string, protocol strin return } -func getRequestLengthMetricValue(requestLengths []float64) float64 { +func getAverageMetricValue(metricValues []float64) float64 { value := 0.0 - if len(requestLengths) > 0 { - sort.Float64s(requestLengths) - requestLengthSum := 0.0 - for _, requestLength := range requestLengths { - requestLengthSum += requestLength + if len(metricValues) > 0 { + sort.Float64s(metricValues) + metricValueSum := 0.0 + for _, metricValue := range metricValues { + metricValueSum += metricValue } - value = requestLengthSum / float64(len(requestLengths)) - } - - return value -} - -func getGzipRatioMetricValue(gzipRatios []float64) float64 { - value := 0.0 - - if len(gzipRatios) > 0 { - sort.Float64s(gzipRatios) - gzipRatioSum := 0.0 - for _, gzipRatio := range gzipRatios { - gzipRatioSum += gzipRatio - } - value = gzipRatioSum / float64(len(gzipRatios)) + value = metricValueSum / float64(len(metricValues)) } return value @@ -472,6 +489,8 @@ func convertLogFormat(logFormat string) string { newLogFormat = strings.ReplaceAll(newLogFormat, "$request ", "%{DATA:request} ") newLogFormat = strings.ReplaceAll(newLogFormat, "$upstream_connect_time", "%{DATA:upstream_connect_time}") newLogFormat = strings.ReplaceAll(newLogFormat, "$upstream_header_time", "%{DATA:upstream_header_time}") + newLogFormat = strings.ReplaceAll(newLogFormat, "$upstream_response_time", "%{DATA:upstream_response_time}") + newLogFormat = strings.ReplaceAll(newLogFormat, "$upstream_response_length", "%{DATA:upstream_response_length}") newLogFormat = strings.ReplaceAll(newLogFormat, "[", "\\[") newLogFormat = strings.ReplaceAll(newLogFormat, "]", "\\]") return newLogFormat @@ -486,7 +505,7 @@ func isOtherMethod(method string) bool { method != "method.options" } -func getDefaultCounters() (map[string]float64, map[string]float64, map[string]float64) { +func getDefaultCounters() (map[string]float64, map[string]float64, map[string]float64, map[string]float64, map[string]float64) { httpCounters := map[string]float64{ "gzip.ratio": 0, "method.delete": 0, @@ -539,5 +558,17 @@ func getDefaultCounters() (map[string]float64, map[string]float64, map[string]fl "upstream.header.time.pctl95": 0, } - return httpCounters, upstreamConnectCounters, upstreamHeaderCounters + upstreamResponseTimeCounters := map[string]float64{ + "upstream.response.time": 0, + "upstream.response.time.count": 0, + "upstream.response.time.max": 0, + "upstream.response.time.median": 0, + "upstream.response.time.pctl95": 0, + } + + upstreamResponseLenCounters := map[string]float64{ + "upstream.response.length": 0, + } + + return httpCounters, upstreamConnectCounters, upstreamHeaderCounters, upstreamResponseTimeCounters, upstreamResponseLenCounters } diff --git a/src/core/metrics/sources/tailer/tailer.go b/src/core/metrics/sources/tailer/tailer.go index dfc6aeb3a..da9ed8adc 100644 --- a/src/core/metrics/sources/tailer/tailer.go +++ b/src/core/metrics/sources/tailer/tailer.go @@ -30,18 +30,20 @@ var ( // NginxAccessItem represents the decoded access log data type NginxAccessItem struct { - BodyBytesSent string `mapstructure:"body_bytes_sent"` - Status string `mapstructure:"status"` - RemoteAddress string `mapstructure:"remote_addr"` - HTTPUserAgent string `mapstructure:"http_user_agent"` - Request string `mapstructure:"request"` - BytesSent string `mapstructure:"bytes_sent"` - RequestLength string `mapstructure:"request_length"` - RequestTime string `mapstructure:"request_time"` - GzipRatio string `mapstructure:"gzip_ratio"` - ServerProtocol string `mapstructure:"server_protocol"` - UpstreamConnectTime string `mapstructure:"upstream_connect_time"` - UpstreamHeaderTime string `mapstructure:"upstream_header_time"` + BodyBytesSent string `mapstructure:"body_bytes_sent"` + Status string `mapstructure:"status"` + RemoteAddress string `mapstructure:"remote_addr"` + HTTPUserAgent string `mapstructure:"http_user_agent"` + Request string `mapstructure:"request"` + BytesSent string `mapstructure:"bytes_sent"` + RequestLength string `mapstructure:"request_length"` + RequestTime string `mapstructure:"request_time"` + GzipRatio string `mapstructure:"gzip_ratio"` + ServerProtocol string `mapstructure:"server_protocol"` + UpstreamConnectTime string `mapstructure:"upstream_connect_time"` + UpstreamHeaderTime string `mapstructure:"upstream_header_time"` + UpstreamResponseTime string `mapstructure:"upstream_response_time"` + UpstreamResponseLength string `mapstructure:"upstream_response_length"` } func NewNginxAccessItem(v map[string]string) (*NginxAccessItem, error) { From a41efaa97cf6ad2f3ada0c153b3eb3f48ca0aade Mon Sep 17 00:00:00 2001 From: Aphral Griffin Date: Thu, 26 Jan 2023 16:52:29 +0000 Subject: [PATCH 2/7] Draft upstream response metrics --- nginx-agent.conf | 9 +-------- 1 file changed, 1 insertion(+), 8 deletions(-) diff --git a/nginx-agent.conf b/nginx-agent.conf index d7ad42009..6be903301 100644 --- a/nginx-agent.conf +++ b/nginx-agent.conf @@ -7,19 +7,12 @@ # are additional agent configuration values that are set via the API and agent install script # which can be found in /etc/nginx-agent/agent-dynamic.conf. -server: - host: 18.197.174.96 - grpcPort: 443 log: # set log level (panic, fatal, error, info, debug, trace; default "info") - level: trace + level: info # set log path. if empty, don't log to file. path: /var/log/nginx-agent/ # data plane status message / 'heartbeat' -tls: - enable: true - skip_verify: true - nginx: # path of NGINX logs to exclude exclude_logs: "" From 0406bca36db435cd18fea6c5525f7a4fca3cf495 Mon Sep 17 00:00:00 2001 From: Aphral Griffin Date: Fri, 3 Feb 2023 12:39:40 +0000 Subject: [PATCH 3/7] draft of upstream response metrics --- src/core/metrics/metrics_util.go | 10 +- src/core/metrics/sources/nginx_access_log.go | 175 +++++++++--------- .../metrics/sources/nginx_access_log_test.go | 78 ++++++-- test/integration/api/api_test.go | 2 +- 4 files changed, 156 insertions(+), 109 deletions(-) diff --git a/src/core/metrics/metrics_util.go b/src/core/metrics/metrics_util.go index 5ea9204f2..d16ab29e2 100644 --- a/src/core/metrics/metrics_util.go +++ b/src/core/metrics/metrics_util.go @@ -141,11 +141,11 @@ func GetCalculationMap() map[string]string { "nginx.upstream.header.time.median": "avg", "nginx.upstream.header.time.pctl95": "avg", "nginx.upstream.response.length": "avg", - "nginx.upstream.response.time": "avg", - "nginx.upstream.response.time.count": "sum", - "nginx.upstream.response.time.max": "avg", - "nginx.upstream.response.median": "avg", - "nginx.upstream.response.time.pctl95": "avg", + "nginx.upstream.response.time": "avg", + "nginx.upstream.response.time.count": "sum", + "nginx.upstream.response.time.max": "avg", + "nginx.upstream.response.median": "avg", + "nginx.upstream.response.time.pctl95": "avg", "nginx.http.conn.handled": "sum", "nginx.http.conn.reading": "avg", "nginx.http.conn.writing": "avg", diff --git a/src/core/metrics/sources/nginx_access_log.go b/src/core/metrics/sources/nginx_access_log.go index feb095194..28017acc7 100644 --- a/src/core/metrics/sources/nginx_access_log.go +++ b/src/core/metrics/sources/nginx_access_log.go @@ -152,22 +152,13 @@ func (c *NginxAccessLog) collectLogStats(ctx context.Context, m chan<- *proto.St c.buf = []*proto.StatsEntity{} } -var httpRequestMetrics = []string{ - "request.time", - "request.time.count", - "request.time.max", - "request.time.median", - "request.time.pctl95", -} - - func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string) { logPattern := convertLogFormat(logFormat) log.Debugf("Collecting from: %s using format: %s", logFile, logFormat) log.Debugf("Pattern used for tailing logs: %s", logPattern) - httpCounters, connCounters, headerCounters, upstreamResponseTimeCounters, upstreamResponseLenCounters := getDefaultCounters() - gzipRatios, requestLengths, requestTimes, upstreamResponseLength, upstreamResponseTimes, connectTimes, headerTimes := []float64{}, []float64{}, []float64{}, []float64{}, []float64{}, []float64{}, []float64{} + httpCounters, upstreamCounters := getDefaultCounters() + gzipRatios, requestLengths, requestTimes, upstreamResponseLength, upstreamResponseTimes, upstreamConnectTimes, upstreamHeaderTimes := []float64{}, []float64{}, []float64{}, []float64{}, []float64{}, []float64{}, []float64{} mu := sync.Mutex{} @@ -247,7 +238,7 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string cTime = strings.ReplaceAll(cTime, "-", "0") if v, err := strconv.ParseFloat(cTime, 64); err == nil { - connectTimes = append(connectTimes, v) + upstreamConnectTimes = append(upstreamConnectTimes, v) } else { log.Debugf("Error getting upstream_connect_time value from access logs, %v", err) } @@ -258,7 +249,7 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string hTime = strings.ReplaceAll(hTime, "-", "0") if v, err := strconv.ParseFloat(hTime, 64); err == nil { - headerTimes = append(headerTimes, v) + upstreamHeaderTimes = append(upstreamHeaderTimes, v) } else { log.Debugf("Error getting upstream_header_time value from access logs: %v", err) } @@ -266,11 +257,11 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string for _, rLength := range strings.Split(access.UpstreamResponseLength, ", ") { rLength = strings.ReplaceAll(rLength, "-", "0") - + if v, err := strconv.ParseFloat(rLength, 64); err == nil { upstreamResponseLength = append(upstreamResponseLength, v) } else { - log.Debug("Error getting upstream_response_length value from access logs: %v", err) + log.Debugf("Error getting upstream_response_length value from access logs: %v", err) } } @@ -280,7 +271,7 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string if v, err := strconv.ParseFloat(rTime, 64); err == nil { upstreamResponseTimes = append(upstreamResponseTimes, v) } else { - log.Debug("Error getting upstream_response_time value from access logs: %v") + log.Debugf("Error getting upstream_response_time value from access logs: %v", err) } } @@ -330,41 +321,48 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string httpCounters["gzip.ratio"] = getAverageMetricValue(gzipRatios) } - for _, metricName := range httpRequestMetrics { - httpCounters[metricName] = getTimeMetrics(metricName, requestTimes) + if len(requestTimes) > 0 { + metricMap := getTimeMetricsMap("request.time", requestTimes) + for metricName, value := range metricMap { + httpCounters[metricName] = value + } } - for metricName := range connCounters { - connCounters[metricName] = getTimeMetrics(metricName, connectTimes) + if len(upstreamConnectTimes) > 0 { + metricMap := getTimeMetricsMap("upstream.connect.time", upstreamConnectTimes) + for metricName, value := range metricMap { + upstreamCounters[metricName] = value + } } - for metricName := range headerCounters { - headerCounters[metricName] = getTimeMetrics(metricName, headerTimes) + if len(upstreamHeaderTimes) > 0 { + metricMap := getTimeMetricsMap("upstream.header.time", upstreamHeaderTimes) + for metricName, value := range metricMap { + upstreamCounters[metricName] = value + } } - for metricName := range upstreamResponseTimeCounters { - upstreamResponseTimeCounters[metricName] = getTimeMetrics(metricName, upstreamResponseTimes) + if len(upstreamResponseTimes) > 0 { + metricMap := getTimeMetricsMap("upstream.response.time", upstreamResponseTimes) + for metricName, value := range metricMap { + upstreamCounters[metricName] = value + } } if len(upstreamResponseLength) > 0 { - upstreamResponseLenCounters["upstream.response.length"] = getAverageMetricValue(upstreamResponseLength) + upstreamCounters["upstream.response.length"] = getAverageMetricValue(upstreamResponseLength) } c.group = "http" simpleMetrics := c.convertSamplesToSimpleMetrics(httpCounters) c.group = "" - simpleMetrics = append(simpleMetrics, c.convertSamplesToSimpleMetrics(connCounters)...) - simpleMetrics = append(simpleMetrics, c.convertSamplesToSimpleMetrics(headerCounters)...) - - c.group = "" - simpleMetrics = append(simpleMetrics, c.convertSamplesToSimpleMetrics(upstreamResponseTimeCounters)...) - simpleMetrics = append(simpleMetrics, c.convertSamplesToSimpleMetrics(upstreamResponseLenCounters)...) + simpleMetrics = append(simpleMetrics, c.convertSamplesToSimpleMetrics(upstreamCounters)...) - log.Tracef("Access log metrics collected: %v", simpleMetrics) + log.Infof("Access log metrics collected: %v", simpleMetrics) // reset the counters - httpCounters, connCounters, headerCounters, upstreamResponseTimeCounters, upstreamResponseLenCounters = getDefaultCounters() - gzipRatios, requestLengths, requestTimes, upstreamResponseLength, upstreamResponseTimes, connectTimes, headerTimes = []float64{}, []float64{}, []float64{}, []float64{}, []float64{}, []float64{}, []float64{} + httpCounters, upstreamCounters = getDefaultCounters() + gzipRatios, requestLengths, requestTimes, upstreamResponseLength, upstreamResponseTimes, upstreamConnectTimes, upstreamHeaderTimes = []float64{}, []float64{}, []float64{}, []float64{}, []float64{}, []float64{}, []float64{} c.buf = append(c.buf, metrics.NewStatsEntity(c.baseDimensions.ToDimensions(), simpleMetrics)) @@ -425,49 +423,59 @@ func getAverageMetricValue(metricValues []float64) float64 { return value } -func getTimeMetrics(metricName string, times []float64) float64 { - if len(times) == 0 { - return 0 +func getTimeMetricsMap(metricName string, times []float64) map[string]float64 { + + metrics := map[string]float64{ + metricName: 0, + metricName + ".count": 0, + metricName + ".median": 0, + metricName + ".max": 0, + metricName + ".pctl95": 0, } - metricType := metricName[strings.LastIndex(metricName, ".")+1:] + for metric := range metrics { - switch metricType { - case "time": - // Calculate average - sum := 0.0 - for _, t := range times { - sum += t - } - return sum / float64(len(times)) + metricType := metric[strings.LastIndex(metric, ".")+1:] - case "count": - return float64(len(times)) + switch metricType { + case "time": + // Calculate average + sum := 0.0 + for _, t := range times { + sum += t + } - case "max": - sort.Float64s(times) - return times[len(times)-1] + metrics[metric] = (math.Round(sum*1000) / 1000) / float64(len(times)) - case "median": - sort.Float64s(times) + case "count": + metrics[metric] = float64(len(times)) - mNumber := len(times) / 2 - if len(times)%2 != 0 { - return times[mNumber] - } else { - return (times[mNumber-1] + times[mNumber]) / 2 - } + case "max": + sort.Float64s(times) + metrics[metric] = times[len(times)-1] - case "pctl95": - sort.Float64s(times) + case "median": + sort.Float64s(times) + + mNumber := len(times) / 2 + if len(times)%2 != 0 { + metrics[metric] = times[mNumber] + } else { + metrics[metric] = (times[mNumber-1] + times[mNumber]) / 2 + } + + case "pctl95": + sort.Float64s(times) + + index := int(math.RoundToEven(float64(0.95)*float64(len(times)))) - 1 + metrics[metric] = times[index] + } - index := int(math.RoundToEven(float64(0.95)*float64(len(times)))) - 1 - return times[index] } - log.Debugf("Could not get time metrics for %s: invalid metric type", metricName) + // log.Debugf("Could not get time metrics for %s: invalid metric type", metricName) - return 0 + return metrics } // convertLogFormat converts log format into a pattern that can be parsed by the tailer @@ -505,7 +513,7 @@ func isOtherMethod(method string) bool { method != "method.options" } -func getDefaultCounters() (map[string]float64, map[string]float64, map[string]float64, map[string]float64, map[string]float64) { +func getDefaultCounters() (map[string]float64, map[string]float64) { httpCounters := map[string]float64{ "gzip.ratio": 0, "method.delete": 0, @@ -542,33 +550,24 @@ func getDefaultCounters() (map[string]float64, map[string]float64, map[string]fl "v2": 0, } - upstreamConnectCounters := map[string]float64{ - "upstream.connect.time": 0, - "upstream.connect.time.count": 0, - "upstream.connect.time.max": 0, - "upstream.connect.time.median": 0, - "upstream.connect.time.pctl95": 0, - } - - upstreamHeaderCounters := map[string]float64{ - "upstream.header.time": 0, - "upstream.header.time.count": 0, - "upstream.header.time.max": 0, - "upstream.header.time.median": 0, - "upstream.header.time.pctl95": 0, - } - - upstreamResponseTimeCounters := map[string]float64{ + upstreamCounters := map[string]float64{ + "upstream.connect.time": 0, + "upstream.connect.time.count": 0, + "upstream.connect.time.max": 0, + "upstream.connect.time.median": 0, + "upstream.connect.time.pctl95": 0, + "upstream.header.time": 0, + "upstream.header.time.count": 0, + "upstream.header.time.max": 0, + "upstream.header.time.median": 0, + "upstream.header.time.pctl95": 0, "upstream.response.time": 0, "upstream.response.time.count": 0, "upstream.response.time.max": 0, "upstream.response.time.median": 0, "upstream.response.time.pctl95": 0, + "upstream.response.length": 0, } - upstreamResponseLenCounters := map[string]float64{ - "upstream.response.length": 0, - } - - return httpCounters, upstreamConnectCounters, upstreamHeaderCounters, upstreamResponseTimeCounters, upstreamResponseLenCounters + return httpCounters, upstreamCounters } diff --git a/src/core/metrics/sources/nginx_access_log_test.go b/src/core/metrics/sources/nginx_access_log_test.go index dab5e819f..a8ac5f9cb 100644 --- a/src/core/metrics/sources/nginx_access_log_test.go +++ b/src/core/metrics/sources/nginx_access_log_test.go @@ -256,27 +256,51 @@ func TestAccessLogStats(t *testing.T) { Name: "nginx.upstream.header.time.pctl95", Value: 0, }, + { + Name: "nginx.upstream.response.length", + Value: 0, + }, + { + Name: "nginx.upstream.response.time", + Value: 0, + }, + { + Name: "nginx.upstream.response.time.count", + Value: 0, + }, + { + Name: "nginx.upstream.response.time.max", + Value: 0, + }, + { + Name: "nginx.upstream.response.time.median", + Value: 0, + }, + { + Name: "nginx.upstream.response.time.pctl95", + Value: 0, + }, }, }, }, { "full_access_log_test", - `$remote_addr - $remote_user [$time_local] "$request" $status $body_bytes_sent "$http_referer" "$http_user_agent" "$http_x_forwarded_for" "$bytes_sent" "$request_length" "$request_time" "$gzip_ratio" "$server_protocol" "$upstream_connect_time" "$upstream_header_time"`, + `$remote_addr - $remote_user [$time_local] "$request" $status $body_bytes_sent "$http_referer" "$http_user_agent" "$http_x_forwarded_for" "$bytes_sent" "$request_length" "$request_time" "$gzip_ratio" "$server_protocol" "$upstream_connect_time" "$upstream_header_time" "$upstream_response_length" "$upstream_response_time"`, []string{ - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"GET /nginx_status HTTP/1.1\" 200 98 \"-\" \"Go-http-client/1.1\" \"-\" \"150\" \"105\" \"0.100\" \"10\" \"HTTP/1.1\" \"350\" \"500\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"POST /nginx_status HTTP/1.1\" 201 98 \"-\" \"Go-http-client/1.1\" \"-\" \"250\" \"110\" \"0.300\" \"20\" \"HTTP/1.1\" \"350\" \"730\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"GET /nginx_status HTTP/1.1\" 200 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"350\" \"500\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"DELETE /nginx_status HTTP/1.1\" 400 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"350\" \"500\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"DELETE /nginx_status HTTP/1.1\" 403 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"100\" \"500\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"HEAD /nginx_status HTTP/1.1\" 404 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"350\" \"505\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"PUT /nginx_status HTTP/1.1\" 499 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"350\" \"2000\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"PUT /nginx_status HTTP/1.1\" 500 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"2350\" \"250\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"OPTIONS /nginx_status HTTP/1.0\" 502 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.0\" \"350\" \"500\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"OPTIONS /nginx_status HTTP/2\" 503 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/2\" \"350\" \"500\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"OPTIONS /nginx_status HTTP/0.9\" 504 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/0.9\" \"350\" \"590\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"OPTIONS /nginx_status HTTP/1.1\" 502 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"900\" \"500\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"TRACE /nginx_status HTTP/1.1\" 200 98 \"-\" \"Go-http-client/1.1\" \"-\" \"150\" \"105\" \"0.100\" \"-\" \"HTTP/1.1\" \"350\" \"170\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"TRACE /nginx_status HTTP/1.1\" 200 98 \"-\" \"Go-http-client/1.1\" \"-\" \"150\" \"105\" \"0.100\" \"-\" \"HTTP/1.1\" \"350\" \"500\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"GET /nginx_status HTTP/1.1\" 200 98 \"-\" \"Go-http-client/1.1\" \"-\" \"150\" \"105\" \"0.100\" \"10\" \"HTTP/1.1\" \"350\" \"500\" \"28\" \"0.00\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"POST /nginx_status HTTP/1.1\" 201 98 \"-\" \"Go-http-client/1.1\" \"-\" \"250\" \"110\" \"0.300\" \"20\" \"HTTP/1.1\" \"350\" \"730\" \"28\" \"0.01\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"GET /nginx_status HTTP/1.1\" 200 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"350\" \"500\" \"28\" \"0.00\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"DELETE /nginx_status HTTP/1.1\" 400 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"350\" \"500\" \"28\" \"0.03\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"DELETE /nginx_status HTTP/1.1\" 403 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"100\" \"500\" \"28\" \"0.00\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"HEAD /nginx_status HTTP/1.1\" 404 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"350\" \"505\" \"28\" \"0.00\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"PUT /nginx_status HTTP/1.1\" 499 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"350\" \"2000\" \"28\" \"0.00\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"PUT /nginx_status HTTP/1.1\" 500 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"2350\" \"250\" \"28\" \"0.02\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"OPTIONS /nginx_status HTTP/1.0\" 502 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.0\" \"350\" \"500\" \"28\" \"0.01\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"OPTIONS /nginx_status HTTP/2\" 503 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/2\" \"350\" \"500\" \"28\" \"0.00\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"OPTIONS /nginx_status HTTP/0.9\" 504 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/0.9\" \"350\" \"590\" \"28\" \"0.00\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"OPTIONS /nginx_status HTTP/1.1\" 502 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"900\" \"500\" \"28\" \"0.00\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"TRACE /nginx_status HTTP/1.1\" 200 98 \"-\" \"Go-http-client/1.1\" \"-\" \"150\" \"105\" \"0.100\" \"-\" \"HTTP/1.1\" \"350\" \"170\" \"28\" \"0.00\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"TRACE /nginx_status HTTP/1.1\" 200 98 \"-\" \"Go-http-client/1.1\" \"-\" \"150\" \"105\" \"0.100\" \"-\" \"HTTP/1.1\" \"350\" \"500\" \"28\" \"0.00\"\n", }, &proto.StatsEntity{ Simplemetrics: []*proto.SimpleMetric{ @@ -452,6 +476,30 @@ func TestAccessLogStats(t *testing.T) { Name: "nginx.upstream.header.time.pctl95", Value: 730, }, + { + Name: "nginx.upstream.response.time", + Value: 0.005, + }, + { + Name: "nginx.upstream.response.time.count", + Value: 14, + }, + { + Name: "nginx.upstream.response.time.max", + Value: 0.03, + }, + { + Name: "nginx.upstream.response.time.median", + Value: 0, + }, + { + Name: "nginx.upstream.response.time.pctl95", + Value: 0.02, + }, + { + Name: "nginx.upstream.response.length", + Value: 28, + }, }, }, }, diff --git a/test/integration/api/api_test.go b/test/integration/api/api_test.go index 77f2cc50c..5a6400672 100644 --- a/test/integration/api/api_test.go +++ b/test/integration/api/api_test.go @@ -33,7 +33,7 @@ func TestAPI_setupTestContainer(t *testing.T) { assert.NoError(t, comp. WaitForService("agent", wait.ForLog("OneTimeRegistration completed")).WithEnv(map[string]string{ - "PACKAGE": os.Getenv("PACKAGE"), + "PACKAGE": os.Getenv("PACKAGE"), "BASE_IMAGE": os.Getenv("BASE_IMAGE"), }). Up(ctx, compose.Wait(true)), "compose.Up()") From 691d145dc25596026f1e4a08eef00e3e95a6876d Mon Sep 17 00:00:00 2001 From: Aphral Griffin Date: Fri, 3 Feb 2023 14:32:52 +0000 Subject: [PATCH 4/7] add upstream response metrics --- src/core/metrics/sources/nginx_access_log.go | 37 +--- .../agent/v2/src/core/metrics/metrics_util.go | 6 + .../core/metrics/sources/nginx_access_log.go | 199 ++++++++++-------- .../src/core/metrics/sources/tailer/tailer.go | 26 +-- 4 files changed, 138 insertions(+), 130 deletions(-) diff --git a/src/core/metrics/sources/nginx_access_log.go b/src/core/metrics/sources/nginx_access_log.go index 28017acc7..af5fb67ef 100644 --- a/src/core/metrics/sources/nginx_access_log.go +++ b/src/core/metrics/sources/nginx_access_log.go @@ -322,31 +322,19 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string } if len(requestTimes) > 0 { - metricMap := getTimeMetricsMap("request.time", requestTimes) - for metricName, value := range metricMap { - httpCounters[metricName] = value - } + getTimeMetricsMap("request.time", requestTimes, httpCounters) } if len(upstreamConnectTimes) > 0 { - metricMap := getTimeMetricsMap("upstream.connect.time", upstreamConnectTimes) - for metricName, value := range metricMap { - upstreamCounters[metricName] = value - } + getTimeMetricsMap("upstream.connect.time", upstreamConnectTimes, upstreamCounters) } if len(upstreamHeaderTimes) > 0 { - metricMap := getTimeMetricsMap("upstream.header.time", upstreamHeaderTimes) - for metricName, value := range metricMap { - upstreamCounters[metricName] = value - } + getTimeMetricsMap("upstream.header.time", upstreamHeaderTimes, upstreamCounters) } if len(upstreamResponseTimes) > 0 { - metricMap := getTimeMetricsMap("upstream.response.time", upstreamResponseTimes) - for metricName, value := range metricMap { - upstreamCounters[metricName] = value - } + getTimeMetricsMap("upstream.response.time", upstreamResponseTimes, upstreamCounters) } if len(upstreamResponseLength) > 0 { @@ -423,7 +411,7 @@ func getAverageMetricValue(metricValues []float64) float64 { return value } -func getTimeMetricsMap(metricName string, times []float64) map[string]float64 { +func getTimeMetricsMap(metricName string, times []float64, counter map[string]float64) { metrics := map[string]float64{ metricName: 0, @@ -445,37 +433,34 @@ func getTimeMetricsMap(metricName string, times []float64) map[string]float64 { sum += t } - metrics[metric] = (math.Round(sum*1000) / 1000) / float64(len(times)) + counter[metric] = (math.Round(sum*1000) / 1000) / float64(len(times)) case "count": - metrics[metric] = float64(len(times)) + counter[metric] = float64(len(times)) case "max": sort.Float64s(times) - metrics[metric] = times[len(times)-1] + counter[metric] = times[len(times)-1] case "median": sort.Float64s(times) mNumber := len(times) / 2 if len(times)%2 != 0 { - metrics[metric] = times[mNumber] + counter[metric] = times[mNumber] } else { - metrics[metric] = (times[mNumber-1] + times[mNumber]) / 2 + counter[metric] = (times[mNumber-1] + times[mNumber]) / 2 } case "pctl95": sort.Float64s(times) index := int(math.RoundToEven(float64(0.95)*float64(len(times)))) - 1 - metrics[metric] = times[index] + counter[metric] = times[index] } } - // log.Debugf("Could not get time metrics for %s: invalid metric type", metricName) - - return metrics } // convertLogFormat converts log format into a pattern that can be parsed by the tailer diff --git a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/metrics_util.go b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/metrics_util.go index af9393d90..d16ab29e2 100644 --- a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/metrics_util.go +++ b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/metrics_util.go @@ -140,6 +140,12 @@ func GetCalculationMap() map[string]string { "nginx.upstream.header.time.max": "avg", "nginx.upstream.header.time.median": "avg", "nginx.upstream.header.time.pctl95": "avg", + "nginx.upstream.response.length": "avg", + "nginx.upstream.response.time": "avg", + "nginx.upstream.response.time.count": "sum", + "nginx.upstream.response.time.max": "avg", + "nginx.upstream.response.median": "avg", + "nginx.upstream.response.time.pctl95": "avg", "nginx.http.conn.handled": "sum", "nginx.http.conn.reading": "avg", "nginx.http.conn.writing": "avg", diff --git a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_access_log.go b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_access_log.go index 124a39415..af5fb67ef 100644 --- a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_access_log.go +++ b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_access_log.go @@ -152,21 +152,13 @@ func (c *NginxAccessLog) collectLogStats(ctx context.Context, m chan<- *proto.St c.buf = []*proto.StatsEntity{} } -var httpRequestMetrics = []string{ - "request.time", - "request.time.count", - "request.time.max", - "request.time.median", - "request.time.pctl95", -} - func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string) { logPattern := convertLogFormat(logFormat) log.Debugf("Collecting from: %s using format: %s", logFile, logFormat) log.Debugf("Pattern used for tailing logs: %s", logPattern) - httpCounters, connCounters, headerCounters := getDefaultCounters() - gzipRatios, requestLengths, requestTimes, connectTimes, headerTimes := []float64{}, []float64{}, []float64{}, []float64{}, []float64{} + httpCounters, upstreamCounters := getDefaultCounters() + gzipRatios, requestLengths, requestTimes, upstreamResponseLength, upstreamResponseTimes, upstreamConnectTimes, upstreamHeaderTimes := []float64{}, []float64{}, []float64{}, []float64{}, []float64{}, []float64{}, []float64{} mu := sync.Mutex{} @@ -246,7 +238,7 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string cTime = strings.ReplaceAll(cTime, "-", "0") if v, err := strconv.ParseFloat(cTime, 64); err == nil { - connectTimes = append(connectTimes, v) + upstreamConnectTimes = append(upstreamConnectTimes, v) } else { log.Debugf("Error getting upstream_connect_time value from access logs, %v", err) } @@ -257,12 +249,32 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string hTime = strings.ReplaceAll(hTime, "-", "0") if v, err := strconv.ParseFloat(hTime, 64); err == nil { - headerTimes = append(headerTimes, v) + upstreamHeaderTimes = append(upstreamHeaderTimes, v) } else { log.Debugf("Error getting upstream_header_time value from access logs: %v", err) } } + for _, rLength := range strings.Split(access.UpstreamResponseLength, ", ") { + rLength = strings.ReplaceAll(rLength, "-", "0") + + if v, err := strconv.ParseFloat(rLength, 64); err == nil { + upstreamResponseLength = append(upstreamResponseLength, v) + } else { + log.Debugf("Error getting upstream_response_length value from access logs: %v", err) + } + + } + + for _, rTime := range strings.Split(access.UpstreamResponseTime, ", ") { + rTime = strings.ReplaceAll(rTime, "-", "0") + if v, err := strconv.ParseFloat(rTime, 64); err == nil { + upstreamResponseTimes = append(upstreamResponseTimes, v) + } else { + log.Debugf("Error getting upstream_response_time value from access logs: %v", err) + } + } + if access.ServerProtocol != "" { if strings.Count(access.ServerProtocol, "/") == 1 { httpProtocolVersion := strings.Split(access.ServerProtocol, "/")[1] @@ -302,37 +314,43 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string mu.Lock() if len(requestLengths) > 0 { - httpCounters["request.length"] = getRequestLengthMetricValue(requestLengths) + httpCounters["request.length"] = getAverageMetricValue(requestLengths) } if len(gzipRatios) > 0 { - httpCounters["gzip.ratio"] = getGzipRatioMetricValue(gzipRatios) + httpCounters["gzip.ratio"] = getAverageMetricValue(gzipRatios) } - for _, metricName := range httpRequestMetrics { - httpCounters[metricName] = getTimeMetrics(metricName, requestTimes) + if len(requestTimes) > 0 { + getTimeMetricsMap("request.time", requestTimes, httpCounters) } - for metricName := range connCounters { - connCounters[metricName] = getTimeMetrics(metricName, connectTimes) + if len(upstreamConnectTimes) > 0 { + getTimeMetricsMap("upstream.connect.time", upstreamConnectTimes, upstreamCounters) } - for metricName := range headerCounters { - headerCounters[metricName] = getTimeMetrics(metricName, headerTimes) + if len(upstreamHeaderTimes) > 0 { + getTimeMetricsMap("upstream.header.time", upstreamHeaderTimes, upstreamCounters) } + if len(upstreamResponseTimes) > 0 { + getTimeMetricsMap("upstream.response.time", upstreamResponseTimes, upstreamCounters) + } + + if len(upstreamResponseLength) > 0 { + upstreamCounters["upstream.response.length"] = getAverageMetricValue(upstreamResponseLength) + } c.group = "http" simpleMetrics := c.convertSamplesToSimpleMetrics(httpCounters) c.group = "" - simpleMetrics = append(simpleMetrics, c.convertSamplesToSimpleMetrics(connCounters)...) - simpleMetrics = append(simpleMetrics, c.convertSamplesToSimpleMetrics(headerCounters)...) + simpleMetrics = append(simpleMetrics, c.convertSamplesToSimpleMetrics(upstreamCounters)...) - log.Tracef("Access log metrics collected: %v", simpleMetrics) + log.Infof("Access log metrics collected: %v", simpleMetrics) // reset the counters - httpCounters, connCounters, headerCounters = getDefaultCounters() - gzipRatios, requestLengths, requestTimes, connectTimes, headerTimes = []float64{}, []float64{}, []float64{}, []float64{}, []float64{} + httpCounters, upstreamCounters = getDefaultCounters() + gzipRatios, requestLengths, requestTimes, upstreamResponseLength, upstreamResponseTimes, upstreamConnectTimes, upstreamHeaderTimes = []float64{}, []float64{}, []float64{}, []float64{}, []float64{}, []float64{}, []float64{} c.buf = append(c.buf, metrics.NewStatsEntity(c.baseDimensions.ToDimensions(), simpleMetrics)) @@ -378,79 +396,71 @@ func getParsedRequest(request string) (method string, uri string, protocol strin return } -func getRequestLengthMetricValue(requestLengths []float64) float64 { +func getAverageMetricValue(metricValues []float64) float64 { value := 0.0 - if len(requestLengths) > 0 { - sort.Float64s(requestLengths) - requestLengthSum := 0.0 - for _, requestLength := range requestLengths { - requestLengthSum += requestLength + if len(metricValues) > 0 { + sort.Float64s(metricValues) + metricValueSum := 0.0 + for _, metricValue := range metricValues { + metricValueSum += metricValue } - value = requestLengthSum / float64(len(requestLengths)) + value = metricValueSum / float64(len(metricValues)) } return value } -func getGzipRatioMetricValue(gzipRatios []float64) float64 { - value := 0.0 +func getTimeMetricsMap(metricName string, times []float64, counter map[string]float64) { - if len(gzipRatios) > 0 { - sort.Float64s(gzipRatios) - gzipRatioSum := 0.0 - for _, gzipRatio := range gzipRatios { - gzipRatioSum += gzipRatio - } - value = gzipRatioSum / float64(len(gzipRatios)) + metrics := map[string]float64{ + metricName: 0, + metricName + ".count": 0, + metricName + ".median": 0, + metricName + ".max": 0, + metricName + ".pctl95": 0, } - return value -} + for metric := range metrics { -func getTimeMetrics(metricName string, times []float64) float64 { - if len(times) == 0 { - return 0 - } + metricType := metric[strings.LastIndex(metric, ".")+1:] - metricType := metricName[strings.LastIndex(metricName, ".")+1:] + switch metricType { + case "time": + // Calculate average + sum := 0.0 + for _, t := range times { + sum += t + } - switch metricType { - case "time": - // Calculate average - sum := 0.0 - for _, t := range times { - sum += t - } - return sum / float64(len(times)) + counter[metric] = (math.Round(sum*1000) / 1000) / float64(len(times)) - case "count": - return float64(len(times)) + case "count": + counter[metric] = float64(len(times)) - case "max": - sort.Float64s(times) - return times[len(times)-1] + case "max": + sort.Float64s(times) + counter[metric] = times[len(times)-1] - case "median": - sort.Float64s(times) + case "median": + sort.Float64s(times) - mNumber := len(times) / 2 - if len(times)%2 != 0 { - return times[mNumber] - } else { - return (times[mNumber-1] + times[mNumber]) / 2 - } + mNumber := len(times) / 2 + if len(times)%2 != 0 { + counter[metric] = times[mNumber] + } else { + counter[metric] = (times[mNumber-1] + times[mNumber]) / 2 + } - case "pctl95": - sort.Float64s(times) + case "pctl95": + sort.Float64s(times) - index := int(math.RoundToEven(float64(0.95)*float64(len(times)))) - 1 - return times[index] - } + index := int(math.RoundToEven(float64(0.95)*float64(len(times)))) - 1 + counter[metric] = times[index] + } - log.Debugf("Could not get time metrics for %s: invalid metric type", metricName) + } - return 0 } // convertLogFormat converts log format into a pattern that can be parsed by the tailer @@ -472,6 +482,8 @@ func convertLogFormat(logFormat string) string { newLogFormat = strings.ReplaceAll(newLogFormat, "$request ", "%{DATA:request} ") newLogFormat = strings.ReplaceAll(newLogFormat, "$upstream_connect_time", "%{DATA:upstream_connect_time}") newLogFormat = strings.ReplaceAll(newLogFormat, "$upstream_header_time", "%{DATA:upstream_header_time}") + newLogFormat = strings.ReplaceAll(newLogFormat, "$upstream_response_time", "%{DATA:upstream_response_time}") + newLogFormat = strings.ReplaceAll(newLogFormat, "$upstream_response_length", "%{DATA:upstream_response_length}") newLogFormat = strings.ReplaceAll(newLogFormat, "[", "\\[") newLogFormat = strings.ReplaceAll(newLogFormat, "]", "\\]") return newLogFormat @@ -486,7 +498,7 @@ func isOtherMethod(method string) bool { method != "method.options" } -func getDefaultCounters() (map[string]float64, map[string]float64, map[string]float64) { +func getDefaultCounters() (map[string]float64, map[string]float64) { httpCounters := map[string]float64{ "gzip.ratio": 0, "method.delete": 0, @@ -523,21 +535,24 @@ func getDefaultCounters() (map[string]float64, map[string]float64, map[string]fl "v2": 0, } - upstreamConnectCounters := map[string]float64{ - "upstream.connect.time": 0, - "upstream.connect.time.count": 0, - "upstream.connect.time.max": 0, - "upstream.connect.time.median": 0, - "upstream.connect.time.pctl95": 0, - } - - upstreamHeaderCounters := map[string]float64{ - "upstream.header.time": 0, - "upstream.header.time.count": 0, - "upstream.header.time.max": 0, - "upstream.header.time.median": 0, - "upstream.header.time.pctl95": 0, + upstreamCounters := map[string]float64{ + "upstream.connect.time": 0, + "upstream.connect.time.count": 0, + "upstream.connect.time.max": 0, + "upstream.connect.time.median": 0, + "upstream.connect.time.pctl95": 0, + "upstream.header.time": 0, + "upstream.header.time.count": 0, + "upstream.header.time.max": 0, + "upstream.header.time.median": 0, + "upstream.header.time.pctl95": 0, + "upstream.response.time": 0, + "upstream.response.time.count": 0, + "upstream.response.time.max": 0, + "upstream.response.time.median": 0, + "upstream.response.time.pctl95": 0, + "upstream.response.length": 0, } - return httpCounters, upstreamConnectCounters, upstreamHeaderCounters + return httpCounters, upstreamCounters } diff --git a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/tailer/tailer.go b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/tailer/tailer.go index dfc6aeb3a..da9ed8adc 100644 --- a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/tailer/tailer.go +++ b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/tailer/tailer.go @@ -30,18 +30,20 @@ var ( // NginxAccessItem represents the decoded access log data type NginxAccessItem struct { - BodyBytesSent string `mapstructure:"body_bytes_sent"` - Status string `mapstructure:"status"` - RemoteAddress string `mapstructure:"remote_addr"` - HTTPUserAgent string `mapstructure:"http_user_agent"` - Request string `mapstructure:"request"` - BytesSent string `mapstructure:"bytes_sent"` - RequestLength string `mapstructure:"request_length"` - RequestTime string `mapstructure:"request_time"` - GzipRatio string `mapstructure:"gzip_ratio"` - ServerProtocol string `mapstructure:"server_protocol"` - UpstreamConnectTime string `mapstructure:"upstream_connect_time"` - UpstreamHeaderTime string `mapstructure:"upstream_header_time"` + BodyBytesSent string `mapstructure:"body_bytes_sent"` + Status string `mapstructure:"status"` + RemoteAddress string `mapstructure:"remote_addr"` + HTTPUserAgent string `mapstructure:"http_user_agent"` + Request string `mapstructure:"request"` + BytesSent string `mapstructure:"bytes_sent"` + RequestLength string `mapstructure:"request_length"` + RequestTime string `mapstructure:"request_time"` + GzipRatio string `mapstructure:"gzip_ratio"` + ServerProtocol string `mapstructure:"server_protocol"` + UpstreamConnectTime string `mapstructure:"upstream_connect_time"` + UpstreamHeaderTime string `mapstructure:"upstream_header_time"` + UpstreamResponseTime string `mapstructure:"upstream_response_time"` + UpstreamResponseLength string `mapstructure:"upstream_response_length"` } func NewNginxAccessItem(v map[string]string) (*NginxAccessItem, error) { From 7a8fd713258a449e993c8666e6c63b7e13ef83ce Mon Sep 17 00:00:00 2001 From: Aphral Griffin Date: Fri, 3 Feb 2023 14:41:36 +0000 Subject: [PATCH 5/7] change log level --- src/core/metrics/sources/nginx_access_log.go | 2 +- .../nginx/agent/v2/src/core/metrics/sources/nginx_access_log.go | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/src/core/metrics/sources/nginx_access_log.go b/src/core/metrics/sources/nginx_access_log.go index af5fb67ef..be102fdab 100644 --- a/src/core/metrics/sources/nginx_access_log.go +++ b/src/core/metrics/sources/nginx_access_log.go @@ -346,7 +346,7 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string c.group = "" simpleMetrics = append(simpleMetrics, c.convertSamplesToSimpleMetrics(upstreamCounters)...) - log.Infof("Access log metrics collected: %v", simpleMetrics) + log.Tracef("Access log metrics collected: %v", simpleMetrics) // reset the counters httpCounters, upstreamCounters = getDefaultCounters() diff --git a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_access_log.go b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_access_log.go index af5fb67ef..be102fdab 100644 --- a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_access_log.go +++ b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_access_log.go @@ -346,7 +346,7 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string c.group = "" simpleMetrics = append(simpleMetrics, c.convertSamplesToSimpleMetrics(upstreamCounters)...) - log.Infof("Access log metrics collected: %v", simpleMetrics) + log.Tracef("Access log metrics collected: %v", simpleMetrics) // reset the counters httpCounters, upstreamCounters = getDefaultCounters() From e86801efb2d93d7b244908cb2ca28b1c898d5fb6 Mon Sep 17 00:00:00 2001 From: Aphral Griffin Date: Fri, 3 Feb 2023 15:05:03 +0000 Subject: [PATCH 6/7] fix name in metrics utils --- src/core/metrics/metrics_util.go | 2 +- .../github.com/nginx/agent/v2/src/core/metrics/metrics_util.go | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/src/core/metrics/metrics_util.go b/src/core/metrics/metrics_util.go index d16ab29e2..2a055e482 100644 --- a/src/core/metrics/metrics_util.go +++ b/src/core/metrics/metrics_util.go @@ -144,7 +144,7 @@ func GetCalculationMap() map[string]string { "nginx.upstream.response.time": "avg", "nginx.upstream.response.time.count": "sum", "nginx.upstream.response.time.max": "avg", - "nginx.upstream.response.median": "avg", + "nginx.upstream.response.time.median": "avg", "nginx.upstream.response.time.pctl95": "avg", "nginx.http.conn.handled": "sum", "nginx.http.conn.reading": "avg", diff --git a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/metrics_util.go b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/metrics_util.go index d16ab29e2..2a055e482 100644 --- a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/metrics_util.go +++ b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/metrics_util.go @@ -144,7 +144,7 @@ func GetCalculationMap() map[string]string { "nginx.upstream.response.time": "avg", "nginx.upstream.response.time.count": "sum", "nginx.upstream.response.time.max": "avg", - "nginx.upstream.response.median": "avg", + "nginx.upstream.response.time.median": "avg", "nginx.upstream.response.time.pctl95": "avg", "nginx.http.conn.handled": "sum", "nginx.http.conn.reading": "avg", From 9f006b3f517e25b03866c437c96138cb49f3b9e8 Mon Sep 17 00:00:00 2001 From: Aphral Griffin Date: Tue, 7 Feb 2023 14:14:48 +0000 Subject: [PATCH 7/7] check values before parsing --- src/core/metrics/sources/nginx_access_log.go | 79 ++++++++++--------- .../core/metrics/sources/nginx_access_log.go | 79 ++++++++++--------- 2 files changed, 80 insertions(+), 78 deletions(-) diff --git a/src/core/metrics/sources/nginx_access_log.go b/src/core/metrics/sources/nginx_access_log.go index be102fdab..8b3bec7b4 100644 --- a/src/core/metrics/sources/nginx_access_log.go +++ b/src/core/metrics/sources/nginx_access_log.go @@ -183,36 +183,46 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string } mu.Lock() - if v, err := strconv.Atoi(access.BodyBytesSent); err == nil { - n := "request.body_bytes_sent" - httpCounters[n] = float64(v) + httpCounters[n] - } else { - log.Debugf("Error getting body_bytes_sent value from access logs: %v", err) + if access.BodyBytesSent != "" { + if v, err := strconv.Atoi(access.BodyBytesSent); err == nil { + n := "request.body_bytes_sent" + httpCounters[n] = float64(v) + httpCounters[n] + } else { + log.Debugf("Error getting body_bytes_sent value from access logs: %v", err) + } } - if v, err := strconv.Atoi(access.BytesSent); err == nil { - n := "request.bytes_sent" - httpCounters[n] = float64(v) + httpCounters[n] - } else { - log.Debugf("Error getting bytes_sent value from access logs: %v", err) + if access.BytesSent != "" { + if v, err := strconv.Atoi(access.BytesSent); err == nil { + n := "request.bytes_sent" + httpCounters[n] = float64(v) + httpCounters[n] + } else { + log.Debugf("Error getting bytes_sent value from access logs: %v", err) + } } - if v, err := strconv.Atoi(access.GzipRatio); err == nil { - gzipRatios = append(gzipRatios, float64(v)) - } else { - log.Debugf("Error getting gzip_ratio value from access logs: %v", err) + if access.GzipRatio != "-" && access.GzipRatio != "" { + if v, err := strconv.Atoi(access.GzipRatio); err == nil { + gzipRatios = append(gzipRatios, float64(v)) + } else { + log.Debugf("Error getting gzip_ratio value from access logs: %v", err) + } } - if v, err := strconv.Atoi(access.RequestLength); err == nil { - requestLengths = append(requestLengths, float64(v)) - } else { - log.Debugf("Error getting request_length value from access logs: %v", err) + if access.RequestLength != "" { + if v, err := strconv.Atoi(access.RequestLength); err == nil { + requestLengths = append(requestLengths, float64(v)) + } else { + log.Debugf("Error getting request_length value from access logs: %v", err) + } } - if v, err := strconv.ParseFloat(access.RequestTime, 64); err == nil { - requestTimes = append(requestTimes, v) - } else { - log.Debugf("Error getting request_time value from access logs: %v", err) + if access.RequestTime != "" { + if v, err := strconv.ParseFloat(access.RequestTime, 64); err == nil { + requestTimes = append(requestTimes, v) + } else { + log.Debugf("Error getting request_time value from access logs: %v", err) + } } if access.Request != "" { @@ -233,32 +243,24 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string } } - for _, cTime := range strings.Split(access.UpstreamConnectTime, ", ") { - // nginx uses '-' to represent TCP connection failures - cTime = strings.ReplaceAll(cTime, "-", "0") - - if v, err := strconv.ParseFloat(cTime, 64); err == nil { + if access.UpstreamConnectTime != "-" && access.UpstreamConnectTime != "" { + if v, err := strconv.ParseFloat(access.UpstreamConnectTime, 64); err == nil { upstreamConnectTimes = append(upstreamConnectTimes, v) } else { log.Debugf("Error getting upstream_connect_time value from access logs, %v", err) } } - for _, hTime := range strings.Split(access.UpstreamHeaderTime, ", ") { - // nginx uses '-' to represent TCP connection failures - hTime = strings.ReplaceAll(hTime, "-", "0") - - if v, err := strconv.ParseFloat(hTime, 64); err == nil { + if access.UpstreamHeaderTime != "-" && access.UpstreamHeaderTime != "" { + if v, err := strconv.ParseFloat(access.UpstreamHeaderTime, 64); err == nil { upstreamHeaderTimes = append(upstreamHeaderTimes, v) } else { log.Debugf("Error getting upstream_header_time value from access logs: %v", err) } } - for _, rLength := range strings.Split(access.UpstreamResponseLength, ", ") { - rLength = strings.ReplaceAll(rLength, "-", "0") - - if v, err := strconv.ParseFloat(rLength, 64); err == nil { + if access.UpstreamResponseLength != "-" && access.UpstreamResponseLength != "" { + if v, err := strconv.ParseFloat(access.UpstreamResponseLength, 64); err == nil { upstreamResponseLength = append(upstreamResponseLength, v) } else { log.Debugf("Error getting upstream_response_length value from access logs: %v", err) @@ -266,9 +268,8 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string } - for _, rTime := range strings.Split(access.UpstreamResponseTime, ", ") { - rTime = strings.ReplaceAll(rTime, "-", "0") - if v, err := strconv.ParseFloat(rTime, 64); err == nil { + if access.UpstreamResponseTime != "-" && access.UpstreamResponseTime != "" { + if v, err := strconv.ParseFloat(access.UpstreamResponseTime, 64); err == nil { upstreamResponseTimes = append(upstreamResponseTimes, v) } else { log.Debugf("Error getting upstream_response_time value from access logs: %v", err) diff --git a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_access_log.go b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_access_log.go index be102fdab..8b3bec7b4 100644 --- a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_access_log.go +++ b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_access_log.go @@ -183,36 +183,46 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string } mu.Lock() - if v, err := strconv.Atoi(access.BodyBytesSent); err == nil { - n := "request.body_bytes_sent" - httpCounters[n] = float64(v) + httpCounters[n] - } else { - log.Debugf("Error getting body_bytes_sent value from access logs: %v", err) + if access.BodyBytesSent != "" { + if v, err := strconv.Atoi(access.BodyBytesSent); err == nil { + n := "request.body_bytes_sent" + httpCounters[n] = float64(v) + httpCounters[n] + } else { + log.Debugf("Error getting body_bytes_sent value from access logs: %v", err) + } } - if v, err := strconv.Atoi(access.BytesSent); err == nil { - n := "request.bytes_sent" - httpCounters[n] = float64(v) + httpCounters[n] - } else { - log.Debugf("Error getting bytes_sent value from access logs: %v", err) + if access.BytesSent != "" { + if v, err := strconv.Atoi(access.BytesSent); err == nil { + n := "request.bytes_sent" + httpCounters[n] = float64(v) + httpCounters[n] + } else { + log.Debugf("Error getting bytes_sent value from access logs: %v", err) + } } - if v, err := strconv.Atoi(access.GzipRatio); err == nil { - gzipRatios = append(gzipRatios, float64(v)) - } else { - log.Debugf("Error getting gzip_ratio value from access logs: %v", err) + if access.GzipRatio != "-" && access.GzipRatio != "" { + if v, err := strconv.Atoi(access.GzipRatio); err == nil { + gzipRatios = append(gzipRatios, float64(v)) + } else { + log.Debugf("Error getting gzip_ratio value from access logs: %v", err) + } } - if v, err := strconv.Atoi(access.RequestLength); err == nil { - requestLengths = append(requestLengths, float64(v)) - } else { - log.Debugf("Error getting request_length value from access logs: %v", err) + if access.RequestLength != "" { + if v, err := strconv.Atoi(access.RequestLength); err == nil { + requestLengths = append(requestLengths, float64(v)) + } else { + log.Debugf("Error getting request_length value from access logs: %v", err) + } } - if v, err := strconv.ParseFloat(access.RequestTime, 64); err == nil { - requestTimes = append(requestTimes, v) - } else { - log.Debugf("Error getting request_time value from access logs: %v", err) + if access.RequestTime != "" { + if v, err := strconv.ParseFloat(access.RequestTime, 64); err == nil { + requestTimes = append(requestTimes, v) + } else { + log.Debugf("Error getting request_time value from access logs: %v", err) + } } if access.Request != "" { @@ -233,32 +243,24 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string } } - for _, cTime := range strings.Split(access.UpstreamConnectTime, ", ") { - // nginx uses '-' to represent TCP connection failures - cTime = strings.ReplaceAll(cTime, "-", "0") - - if v, err := strconv.ParseFloat(cTime, 64); err == nil { + if access.UpstreamConnectTime != "-" && access.UpstreamConnectTime != "" { + if v, err := strconv.ParseFloat(access.UpstreamConnectTime, 64); err == nil { upstreamConnectTimes = append(upstreamConnectTimes, v) } else { log.Debugf("Error getting upstream_connect_time value from access logs, %v", err) } } - for _, hTime := range strings.Split(access.UpstreamHeaderTime, ", ") { - // nginx uses '-' to represent TCP connection failures - hTime = strings.ReplaceAll(hTime, "-", "0") - - if v, err := strconv.ParseFloat(hTime, 64); err == nil { + if access.UpstreamHeaderTime != "-" && access.UpstreamHeaderTime != "" { + if v, err := strconv.ParseFloat(access.UpstreamHeaderTime, 64); err == nil { upstreamHeaderTimes = append(upstreamHeaderTimes, v) } else { log.Debugf("Error getting upstream_header_time value from access logs: %v", err) } } - for _, rLength := range strings.Split(access.UpstreamResponseLength, ", ") { - rLength = strings.ReplaceAll(rLength, "-", "0") - - if v, err := strconv.ParseFloat(rLength, 64); err == nil { + if access.UpstreamResponseLength != "-" && access.UpstreamResponseLength != "" { + if v, err := strconv.ParseFloat(access.UpstreamResponseLength, 64); err == nil { upstreamResponseLength = append(upstreamResponseLength, v) } else { log.Debugf("Error getting upstream_response_length value from access logs: %v", err) @@ -266,9 +268,8 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string } - for _, rTime := range strings.Split(access.UpstreamResponseTime, ", ") { - rTime = strings.ReplaceAll(rTime, "-", "0") - if v, err := strconv.ParseFloat(rTime, 64); err == nil { + if access.UpstreamResponseTime != "-" && access.UpstreamResponseTime != "" { + if v, err := strconv.ParseFloat(access.UpstreamResponseTime, 64); err == nil { upstreamResponseTimes = append(upstreamResponseTimes, v) } else { log.Debugf("Error getting upstream_response_time value from access logs: %v", err)