Addition of latency_usec histogram metric (#770)

* Addition of latency_usec histogram metric

exporter/exporter.go

@@ -347,6 +347,7 @@ func NewRedisExporter(redisURI string, opts Options) (*Exporter, error) {
 		"commands_failed_calls_total":                  {txt: `Total number of errors prior command execution per command`, lbls: []string{"cmd"}},
 		"commands_rejected_calls_total":                {txt: `Total number of errors within command execution per command`, lbls: []string{"cmd"}},
 		"commands_total":                               {txt: `Total number of calls per command`, lbls: []string{"cmd"}},
+		"commands_latencies_usec":                      {txt: `A histogram of latencies per command`, lbls: []string{"cmd"}},
 		"latency_percentiles_usec":                     {txt: `A summary of latency percentile distribution per command`, lbls: []string{"cmd"}},
 		"config_key_value":                             {txt: `Config key and value`, lbls: []string{"key", "value"}},
 		"config_value":                                 {txt: `Config key and value as metric`, lbls: []string{"key"}},
@@ -613,7 +614,7 @@ func (e *Exporter) scrapeRedisHost(ch chan<- prometheus.Metric) error {
 
 	e.extractInfoMetrics(ch, infoAll, dbCount)
 
-	e.extractLatencyMetrics(ch, c)
+	e.extractLatencyMetrics(ch, infoAll, c)
 
 	if e.options.IsCluster {
 		clusterClient, err := e.connectToRedisCluster()

exporter/latency.go

@@ -1,23 +1,36 @@
 package exporter
 
 import (
+	"regexp"
+	"strconv"
+	"strings"
+
 	"sync"
 
 	"github.com/gomodule/redigo/redis"
 	"github.com/prometheus/client_golang/prometheus"
 	log "github.com/sirupsen/logrus"
 )
 
-var logErrOnce sync.Once
+var (
+	logLatestErrOnce, logHistogramErrOnce sync.Once
+
+	extractUsecRegexp = regexp.MustCompile(`(?m)^cmdstat_([a-zA-Z0-9\|]+):.*usec=([0-9]+).*$`)
+)
+
+func (e *Exporter) extractLatencyMetrics(ch chan<- prometheus.Metric, infoAll string, c redis.Conn) {
+	e.extractLatencyLatestMetrics(ch, c)
+	e.extractLatencyHistogramMetrics(ch, infoAll, c)
+}
 
-func (e *Exporter) extractLatencyMetrics(ch chan<- prometheus.Metric, c redis.Conn) {
-	reply, err := redis.Values(doRedisCmd(c, "LATENCY", "LATEST"))
+func (e *Exporter) extractLatencyLatestMetrics(outChan chan<- prometheus.Metric, redisConn redis.Conn) {
+	reply, err := redis.Values(doRedisCmd(redisConn, "LATENCY", "LATEST"))
 	if err != nil {
 		/*
 			this can be a little too verbose, see e.g. https://github.com/oliver006/redis_exporter/issues/495
 			we're logging this only once as an Error and always as Debugf()
 		*/
-		logErrOnce.Do(func() {
+		logLatestErrOnce.Do(func() {
 			log.Errorf("WARNING, LOGGED ONCE ONLY: cmd LATENCY LATEST, err: %s", err)
 		})
 		log.Debugf("cmd LATENCY LATEST, err: %s", err)
@@ -30,9 +43,66 @@ func (e *Exporter) extractLatencyMetrics(ch chan<- prometheus.Metric, c redis.Co
 			var spikeLast, spikeDuration, max int64
 			if _, err := redis.Scan(latencyResult, &eventName, &spikeLast, &spikeDuration, &max); err == nil {
 				spikeDurationSeconds := float64(spikeDuration) / 1e3
-				e.registerConstMetricGauge(ch, "latency_spike_last", float64(spikeLast), eventName)
-				e.registerConstMetricGauge(ch, "latency_spike_duration_seconds", spikeDurationSeconds, eventName)
+				e.registerConstMetricGauge(outChan, "latency_spike_last", float64(spikeLast), eventName)
+				e.registerConstMetricGauge(outChan, "latency_spike_duration_seconds", spikeDurationSeconds, eventName)
 			}
 		}
 	}
 }
+
+func (e *Exporter) extractLatencyHistogramMetrics(outChan chan<- prometheus.Metric, infoAll string, redisConn redis.Conn) {
+	reply, err := redis.Values(doRedisCmd(redisConn, "LATENCY", "HISTOGRAM"))
+	if err != nil {
+		logHistogramErrOnce.Do(func() {
+			log.Errorf("WARNING, LOGGED ONCE ONLY: cmd LATENCY HISTOGRAM, err: %s", err)
+		})
+		log.Debugf("cmd LATENCY HISTOGRAM, err: %s", err)
+		return
+	}
+
+	for i := 0; i < len(reply); i += 2 {
+		cmd, _ := redis.String(reply[i], nil)
+		details, _ := redis.Values(reply[i+1], nil)
+
+		var totalCalls uint64
+		var bucketInfo []uint64
+
+		if _, err := redis.Scan(details, nil, &totalCalls, nil, &bucketInfo); err != nil {
+			break
+		}
+
+		buckets := map[float64]uint64{}
+
+		for j := 0; j < len(bucketInfo); j += 2 {
+			usec := float64(bucketInfo[j])
+			count := bucketInfo[j+1]
+			buckets[usec] = count
+		}
+
+		totalUsecs := extractTotalUsecForCommand(infoAll, cmd)
+
+		labelValues := []string{"cmd"}
+		e.registerConstHistogram(outChan, "commands_latencies_usec", labelValues, totalCalls, float64(totalUsecs), buckets, cmd)
+	}
+}
+
+func extractTotalUsecForCommand(infoAll string, cmd string) uint64 {
+	total := uint64(0)
+
+	matches := extractUsecRegexp.FindAllStringSubmatch(infoAll, -1)
+	for _, match := range matches {
+		if !strings.HasPrefix(match[1], cmd) {
+			continue
+		}
+
+		usecs, err := strconv.ParseUint(match[2], 10, 0)
+		if err != nil {
+			log.Warnf("Unable to parse uint from string \"%s\": %v", match[2], err)
+			continue
+		}
+
+		total += usecs
+	}
+
+	return total
+}

exporter/latency_test.go

@@ -1,6 +1,7 @@
 package exporter
 
 import (
+	"fmt"
 	"math"
 	"os"
 	"strings"
@@ -104,3 +105,45 @@ func resetLatency(t *testing.T, addr string) error {
 
 	return nil
 }
+
+func TestLatencyHistogram(t *testing.T) {
+	redisSevenAddr := os.Getenv("TEST_REDIS7_URI")
+
+	// Since Redis v7 we should have latency histogram stats
+	e := getTestExporterWithAddr(redisSevenAddr)
+	setupDBKeys(t, redisSevenAddr)
+
+	want := map[string]bool{"commands_latencies_usec": false}
+	commandStatsCheck(t, e, want)
+	deleteKeysFromDB(t, redisSevenAddr)
+}
+
+func TestExtractTotalUsecForCommand(t *testing.T) {
+	statsOutString := `# Commandstats
+cmdstat_testerr|1:calls=1,usec_per_call=5.00,rejected_calls=0,failed_calls=0
+cmdstat_testerr:calls=1,usec=2,usec_per_call=5.00,rejected_calls=0,failed_calls=0
+cmdstat_testerr2:calls=1,usec=-2,usec_per_call=5.00,rejected_calls=0,failed_calls=0
+cmdstat_testerr3:calls=1,usec=` + fmt.Sprintf("%d1", uint64(math.MaxUint64)) + `,usec_per_call=5.00,rejected_calls=0,failed_calls=0
+cmdstat_config|get:calls=69103,usec=15005068,usec_per_call=217.14,rejected_calls=0,failed_calls=0
+cmdstat_config|set:calls=3,usec=58,usec_per_call=19.33,rejected_calls=0,failed_calls=3
+
+# Latencystats
+latency_percentiles_usec_pubsub|channels:p50=5.023,p99=5.023,p99.9=5.023
+latency_percentiles_usec_config|get:p50=272.383,p99=346.111,p99.9=395.263
+latency_percentiles_usec_config|set:p50=23.039,p99=27.007,p99.9=27.007`
+
+	testMap := map[string]uint64{
+		"config|set": 58,
+		"config":     58 + 15005068,
+		"testerr|1":  0,
+		"testerr":    2 + 0,
+		"testerr2":   0,
+		"testerr3":   0,
+	}
+
+	for cmd, expected := range testMap {
+		if res := extractTotalUsecForCommand(statsOutString, cmd); res != expected {
+			t.Errorf("Incorrect usec extracted. Expected %d but got %d!", expected, res)
+		}
+	}
+}

exporter/metrics.go

@@ -80,27 +80,45 @@ func (e *Exporter) registerConstMetricGauge(ch chan<- prometheus.Metric, metric
 }
 
 func (e *Exporter) registerConstMetric(ch chan<- prometheus.Metric, metric string, val float64, valType prometheus.ValueType, labelValues ...string) {
-	descr := e.metricDescriptions[metric]
-	if descr == nil {
-		descr = newMetricDescr(e.options.Namespace, metric, metric+" metric", labelValues)
-	}
+	description := e.findOrCreateMetricDescription(metric, labelValues)
 
-	if m, err := prometheus.NewConstMetric(descr, valType, val, labelValues...); err == nil {
+	if m, err := prometheus.NewConstMetric(description, valType, val, labelValues...); err == nil {
 		ch <- m
 	}
 }
 
 func (e *Exporter) registerConstSummary(ch chan<- prometheus.Metric, metric string, labelValues []string, count uint64, sum float64, latencyMap map[float64]float64, cmd string) {
-	descr := e.metricDescriptions[metric]
-	if descr == nil {
-		descr = newMetricDescr(e.options.Namespace, metric, metric+" metric", labelValues)
-	}
+	description := e.findOrCreateMetricDescription(metric, labelValues)
+
 	// Create a constant summary from values we got from a 3rd party telemetry system.
-	s := prometheus.MustNewConstSummary(
-		descr,
+	summary := prometheus.MustNewConstSummary(
+		description,
 		count, sum,
 		latencyMap,
 		cmd,
 	)
-	ch <- s
+	ch <- summary
+}
+
+func (e *Exporter) registerConstHistogram(ch chan<- prometheus.Metric, metric string, labelValues []string, count uint64, sum float64, buckets map[float64]uint64, cmd string) {
+	description := e.findOrCreateMetricDescription(metric, labelValues)
+
+	histogram := prometheus.MustNewConstHistogram(
+		description,
+		count, sum,
+		buckets,
+		cmd,
+	)
+	ch <- histogram
+}
+
+func (e *Exporter) findOrCreateMetricDescription(metricName string, labels []string) *prometheus.Desc {
+	description, found := e.metricDescriptions[metricName]
+
+	if !found {
+		description = newMetricDescr(e.options.Namespace, metricName, metricName+" metric", labels)
+		e.metricDescriptions[metricName] = description
+	}
+
+	return description
 }

exporter/metrics_test.go

@@ -1,7 +1,10 @@
 package exporter
 
 import (
+	"strings"
 	"testing"
+
+	"github.com/prometheus/client_golang/prometheus"
 )
 
 func TestSanitizeMetricName(t *testing.T) {
@@ -16,3 +19,55 @@ func TestSanitizeMetricName(t *testing.T) {
 		}
 	}
 }
+
+func TestRegisterConstHistogram(t *testing.T) {
+	exp := getTestExporter()
+
+	metricName := "foo"
+
+	ch := make(chan prometheus.Metric)
+	go func() {
+		exp.registerConstHistogram(ch, metricName, []string{"bar"}, 12, .24, map[float64]uint64{}, "test")
+		close(ch)
+	}()
+
+	for m := range ch {
+		if strings.Contains(m.Desc().String(), metricName) {
+			return
+		}
+	}
+	t.Errorf("Histogram was not registered")
+}
+
+func TestFindOrCreateMetricsDescriptionFindExisting(t *testing.T) {
+	exp := getTestExporter()
+	exp.metricDescriptions = map[string]*prometheus.Desc{}
+
+	metricName := "foo"
+	labels := []string{"1", "2"}
+
+	ret := exp.findOrCreateMetricDescription(metricName, labels)
+	ret2 := exp.findOrCreateMetricDescription(metricName, labels)
+
+	if ret == nil || ret2 == nil || ret != ret2 {
+		t.Errorf("Unexpected return values: (%v, %v)", ret, ret2)
+	}
+
+	if len(exp.metricDescriptions) != 1 {
+		t.Errorf("Unexpected metricDescriptions entry count.")
+	}
+}
+
+func TestFindOrCreateMetricsDescriptionCreateNew(t *testing.T) {
+	exp := getTestExporter()
+	exp.metricDescriptions = map[string]*prometheus.Desc{}
+
+	metricName := "foo"
+	labels := []string{"1", "2"}
+
+	ret := exp.findOrCreateMetricDescription(metricName, labels)
+
+	if ret == nil {
+		t.Errorf("Unexpected return value: %s", ret)
+	}
+}