Fix podLatency measurement

Signed-off-by: Raul Sevilla <rsevilla@redhat.com>
kube-burner · Nov 16, 2020 · 692e828 · 692e828
1 parent 3b0d456
commit 692e828
Show file tree

Hide file tree

Showing 2 changed files with 68 additions and 62 deletions.
diff --git a/README.md b/README.md
@@ -390,57 +390,62 @@ Measurements are enabled in the measurements section of the configuration file.
 Collects latencies from the different pod startup phases, these **latency metrics are in ms**. Can be enabled with:
 
 ```yaml
-    measurements:
-    - name: podLatency
-      esIndex: kube-burner-podlatency
+  measurements:
+  - name: podLatency
+    esIndex: kube-burner-podlatency
 ```
 
 This measurement sends its metrics to the index configured by *esIndex*. The metrics collected are pod latency histograms and pod latency quantiles P99, P95 and P50.
 
 Pod latency sample:
 ```json
 {
-    "uuid": "363073c1-5752-4a36-8e0a-1311fa7663f8",
-    "timestamp": "2020-08-24T19:05:49.316913942+02:00",
-    "schedulingLatency": 8,
-    "initializedLatency": 82,
-    "containersReadyLatency": 82,
-    "podReadyLatency": 82,
-    "metricName": "podLatencyMeasurement",
-    "jobName": "kube-burner-job"
+  "timestamp": "2020-11-15T20:28:59.598727718Z",
+  "schedulingLatency": 4,
+  "initializedLatency": 20,
+  "containersReadyLatency": 2997,
+  "podReadyLatency": 2997,
+  "metricName": "podLatencyMeasurement",
+  "jobName": "kubelet-density",
+  "uuid": "c40b4346-7af7-4c63-9ab4-aae7ccdd0616",
+  "namespace": "kubelet-density",
+  "podName": "kubelet-density-13",
+  "jobName": "kube-burner-job"
 }
 ```
 
 Pod latency quantile sample:
 
 ```json
 {
-    "quantileName": "initialized",
-    "uuid": "363073c1-5752-4a36-8e0a-1311fa7663f8",
-    "P99": 76543,
-    "P95": 72702,
-    "P50": 336,
-    "Max": 84523,
-    "Avg": 53131,
-    "timestamp": "2020-08-27T01:13:24.091110065+02:00",
-    "metricName": "podLatencyQuantilesMeasurement",
-    "jobName": "kube-burner-job"
+  "quantileName": "podReady",
+  "uuid": "23c0b5fd-c17e-4326-a389-b3aebc774c82",
+  "P99": 3774,
+  "P95": 3510,
+  "P50": 2897,
+  "max": 3774,
+  "avg": 2876.3,
+  "timestamp": "2020-11-15T22:26:51.553221077+01:00",
+  "metricName": "podLatencyQuantilesMeasurement",
+  "jobName": "kubelet-density"
 },
 {
-    "quantileName": "podReady",
-    "uuid": "363073c1-5752-4a36-8e0a-1311fa7663f8",
-    "P99": 76543,
-    "P95": 72702,
-    "P50": 336,
-    "Max": 82522,
-    "Avg": 54153,
-    "timestamp": "2020-08-27T01:13:24.091110483+02:00",
-    "metricName": "podLatencyQuantilesMeasurement",
-    "jobName": "kube-burner-job"
+  "quantileName": "scheduling",
+  "uuid": "23c0b5fd-c17e-4326-a389-b3aebc774c82",
+  "P99": 64,
+  "P95": 8,
+  "P50": 5,
+  "max": 64,
+  "avg": 5.38,
+  "timestamp": "2020-11-15T22:26:51.553225151+01:00",
+  "metricName": "podLatencyQuantilesMeasurement",
+  "jobName": "kubelet-density"
 }
 ```
 
-The __esIndex__ option can be used to configure the ES index where metrics will be indexed.
+More information about the pod lifecycle can be found in the [kubernetes docs](https://kubernetes.io/docs/concepts/workloads/pods/pod-lifecycle/).
+
+**Note**: The __esIndex__ option can be used to configure the ES index where metrics will be indexed.
 
 #### Pprof collection
 

diff --git a/pkg/measurements/pod_latency.go b/pkg/measurements/pod_latency.go
@@ -34,13 +34,13 @@ import (
 type podMetric struct {
 	Timestamp              time.Time `json:"timestamp"`
 	scheduled              time.Time
-	SchedulingLatency      int64 `json:"schedulingLatency"`
+	SchedulingLatency      int `json:"schedulingLatency"`
 	initialized            time.Time
-	InitializedLatency     int64 `json:"initializedLatency"`
+	InitializedLatency     int `json:"initializedLatency"`
 	containersReady        time.Time
-	ContainersReadyLatency int64 `json:"containersReadyLatency"`
+	ContainersReadyLatency int `json:"containersReadyLatency"`
 	podReady               time.Time
-	PodReadyLatency        int64  `json:"podReadyLatency"`
+	PodReadyLatency        int    `json:"podReadyLatency"`
 	MetricName             string `json:"metricName"`
 	JobName                string `json:"jobName"`
 	UUID                   string `json:"uuid"`
@@ -99,23 +99,24 @@ func (p *podLatency) createPod(obj interface{}) {
 
 func (p *podLatency) updatePod(obj interface{}) {
 	pod := obj.(*v1.Pod)
-	if pm, exists := podMetrics[string(pod.UID)]; exists {
+	if pm, exists := podMetrics[string(pod.UID)]; exists && pm.podReady.IsZero() {
 		for _, c := range pod.Status.Conditions {
-			switch c.Type {
-			case v1.PodScheduled:
-				if pm.scheduled.IsZero() {
-					pm.scheduled = time.Now().UTC()
-				}
-			case v1.PodInitialized:
-				if pm.initialized.IsZero() {
-					pm.initialized = time.Now().UTC()
-				}
-			case v1.ContainersReady:
-				if pm.containersReady.IsZero() {
-					pm.containersReady = time.Now().UTC()
-				}
-			case v1.PodReady:
-				if pm.podReady.IsZero() {
+			if c.Status == v1.ConditionTrue {
+				switch c.Type {
+				case v1.PodScheduled:
+					if pm.scheduled.IsZero() {
+						pm.scheduled = time.Now().UTC()
+					}
+				case v1.PodInitialized:
+					if pm.initialized.IsZero() {
+						pm.initialized = time.Now().UTC()
+					}
+				case v1.ContainersReady:
+					if pm.containersReady.IsZero() {
+						pm.containersReady = time.Now().UTC()
+					}
+				case v1.PodReady:
+					log.Debugf("Pod %s is ready", pod.Name)
 					pm.podReady = time.Now().UTC()
 				}
 			}
@@ -155,7 +156,7 @@ func (p *podLatency) writeToFile() error {
 		if factory.globalConfig.MetricsDirectory != "" {
 			err := os.MkdirAll(factory.globalConfig.MetricsDirectory, 0744)
 			if err != nil {
-				return fmt.Errorf("Error creating metrics directory %s: ", err)
+				return fmt.Errorf("Error creating metrics directory: %s", err)
 			}
 			filename = path.Join(factory.globalConfig.MetricsDirectory, filename)
 		}
@@ -165,7 +166,7 @@ func (p *podLatency) writeToFile() error {
 		}
 		defer f.Close()
 		jsonEnc := json.NewEncoder(f)
-		jsonEnc.SetIndent("", "    ")
+		jsonEnc.SetIndent("", "  ")
 		log.Infof("Writing pod latency metrics in %s", filename)
 		if err := jsonEnc.Encode(data); err != nil {
 			return fmt.Errorf("JSON encoding error: %s", err)
@@ -220,10 +221,10 @@ func (p *podLatency) index() {
 
 func normalizeMetrics() {
 	for _, m := range podMetrics {
-		m.SchedulingLatency = m.scheduled.Sub(m.Timestamp).Milliseconds()
-		m.ContainersReadyLatency = m.containersReady.Sub(m.Timestamp).Milliseconds()
-		m.InitializedLatency = m.initialized.Sub(m.Timestamp).Milliseconds()
-		m.PodReadyLatency = m.podReady.Sub(m.Timestamp).Milliseconds()
+		m.SchedulingLatency = int(m.scheduled.Sub(m.Timestamp).Milliseconds())
+		m.ContainersReadyLatency = int(m.containersReady.Sub(m.Timestamp).Milliseconds())
+		m.InitializedLatency = int(m.initialized.Sub(m.Timestamp).Milliseconds())
+		m.PodReadyLatency = int(m.podReady.Sub(m.Timestamp).Milliseconds())
 		normLatencies = append(normLatencies, m)
 	}
 }
@@ -232,10 +233,10 @@ func calcQuantiles() {
 	quantiles := []float64{0.5, 0.95, 0.99}
 	quantileMap := map[string][]int{}
 	for _, l := range normLatencies {
-		quantileMap["scheduling"] = append(quantileMap["scheduling"], int(l.(podMetric).SchedulingLatency))
-		quantileMap["containersReady"] = append(quantileMap["containersReady"], int(l.(podMetric).ContainersReadyLatency))
-		quantileMap["initialized"] = append(quantileMap["initialized"], int(l.(podMetric).InitializedLatency))
-		quantileMap["podReady"] = append(quantileMap["podReady"], int(l.(podMetric).PodReadyLatency))
+		quantileMap["scheduling"] = append(quantileMap["scheduling"], l.(podMetric).SchedulingLatency)
+		quantileMap["containersReady"] = append(quantileMap["containersReady"], l.(podMetric).ContainersReadyLatency)
+		quantileMap["initialized"] = append(quantileMap["initialized"], l.(podMetric).InitializedLatency)
+		quantileMap["podReady"] = append(quantileMap["podReady"], l.(podMetric).PodReadyLatency)
 	}
 	for quantileName, v := range quantileMap {
 		podQ := podLatencyQuantiles{