From 55b5e6dc33b97d1b2af5ddce8ee41f887ccb1d3a Mon Sep 17 00:00:00 2001
From: Hemant Kumar <hekumar@redhat.com>
Date: Mon, 13 Dec 2021 16:23:01 -0500
Subject: [PATCH 1/2] Add metric for reporting total end-to-end mount time

This metric includes time spent in waiting for devices to be attached,
any RPC calls and performing recursive chown etc.
---
 .../volumemanager/cache/desired_state_of_world.go      | 10 ++++++++++
 .../util/operationexecutor/operation_executor.go       |  3 +++
 .../util/operationexecutor/operation_generator.go      |  6 ++++++
 3 files changed, 19 insertions(+)

diff --git a/pkg/kubelet/volumemanager/cache/desired_state_of_world.go b/pkg/kubelet/volumemanager/cache/desired_state_of_world.go
index e56e13b1794..c96b804a377 100644
--- a/pkg/kubelet/volumemanager/cache/desired_state_of_world.go
+++ b/pkg/kubelet/volumemanager/cache/desired_state_of_world.go
@@ -23,6 +23,7 @@ package cache
 import (
 	"fmt"
 	"sync"
+	"time"
 
 	v1 "k8s.io/api/core/v1"
 	"k8s.io/apimachinery/pkg/api/resource"
@@ -207,6 +208,8 @@ type podToMount struct {
 	// volume claim, this contains the volume.Spec.Name() of the persistent
 	// volume claim
 	outerVolumeSpecName string
+	// mountRequestTime stores time at which mount was requested
+	mountRequestTime time.Time
 }
 
 const (
@@ -281,6 +284,11 @@ func (dsw *desiredStateOfWorld) AddPodToVolume(
 			desiredSizeLimit:        sizeLimit,
 		}
 	}
+	oldPodMount, ok := dsw.volumesToMount[volumeName].podsToMount[podName]
+	mountRequestTime := time.Now()
+	if ok && !volumePlugin.RequiresRemount(volumeSpec) {
+		mountRequestTime = oldPodMount.mountRequestTime
+	}
 
 	// Create new podToMount object. If it already exists, it is refreshed with
 	// updated values (this is required for volumes that require remounting on
@@ -290,6 +298,7 @@ func (dsw *desiredStateOfWorld) AddPodToVolume(
 		pod:                 pod,
 		volumeSpec:          volumeSpec,
 		outerVolumeSpecName: outerVolumeSpecName,
+		mountRequestTime:    mountRequestTime,
 	}
 	return volumeName, nil
 }
@@ -407,6 +416,7 @@ func (dsw *desiredStateOfWorld) GetVolumesToMount() []VolumeToMount {
 						OuterVolumeSpecName:     podObj.outerVolumeSpecName,
 						VolumeGidValue:          volumeObj.volumeGidValue,
 						ReportedInUse:           volumeObj.reportedInUse,
+						MountRequestTime:        podObj.mountRequestTime,
 						DesiredSizeLimit:        volumeObj.desiredSizeLimit}})
 		}
 	}
diff --git a/pkg/volume/util/operationexecutor/operation_executor.go b/pkg/volume/util/operationexecutor/operation_executor.go
index ca4f6ca0cf9..dda1d43c220 100644
--- a/pkg/volume/util/operationexecutor/operation_executor.go
+++ b/pkg/volume/util/operationexecutor/operation_executor.go
@@ -387,6 +387,9 @@ type VolumeToMount struct {
 	// DesiredSizeLimit indicates the desired upper bound on the size of the volume
 	// (if so implemented)
 	DesiredSizeLimit *resource.Quantity
+
+	// time at which volume was requested to be mounted
+	MountRequestTime time.Time
 }
 
 // DeviceMountState represents device mount state in a global path.
diff --git a/pkg/volume/util/operationexecutor/operation_generator.go b/pkg/volume/util/operationexecutor/operation_generator.go
index d7cb5121a6c..eaa4f58a269 100644
--- a/pkg/volume/util/operationexecutor/operation_generator.go
+++ b/pkg/volume/util/operationexecutor/operation_generator.go
@@ -777,6 +777,12 @@ func (og *operationGenerator) GenerateMountVolumeFunc(
 			}
 		}
 
+		// record total time it takes to mount a volume. This is end to end time that includes waiting for volume to attach, node to be update
+		// plugin call to succeed
+		mountRequestTime := volumeToMount.MountRequestTime
+		totalTimeTaken := time.Since(mountRequestTime).Seconds()
+		util.RecordOperationLatencyMetric(util.GetFullQualifiedPluginNameForVolume(volumePluginName, volumeToMount.VolumeSpec), "volume_mount", totalTimeTaken)
+
 		markVolMountedErr := actualStateOfWorld.MarkVolumeAsMounted(markOpts)
 		if markVolMountedErr != nil {
 			// On failure, return error. Caller will log and retry.

From c9177f308389983b17b6ae7b9f7b7a8d47d3c5b4 Mon Sep 17 00:00:00 2001
From: Hemant Kumar <hekumar@redhat.com>
Date: Thu, 6 Jan 2022 12:51:05 -0500
Subject: [PATCH 2/2] rename volume_mount to overall_volume_mount for total
 metric time

---
 pkg/volume/util/operationexecutor/operation_generator.go | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/pkg/volume/util/operationexecutor/operation_generator.go b/pkg/volume/util/operationexecutor/operation_generator.go
index eaa4f58a269..5fdeff9312f 100644
--- a/pkg/volume/util/operationexecutor/operation_generator.go
+++ b/pkg/volume/util/operationexecutor/operation_generator.go
@@ -781,7 +781,7 @@ func (og *operationGenerator) GenerateMountVolumeFunc(
 		// plugin call to succeed
 		mountRequestTime := volumeToMount.MountRequestTime
 		totalTimeTaken := time.Since(mountRequestTime).Seconds()
-		util.RecordOperationLatencyMetric(util.GetFullQualifiedPluginNameForVolume(volumePluginName, volumeToMount.VolumeSpec), "volume_mount", totalTimeTaken)
+		util.RecordOperationLatencyMetric(util.GetFullQualifiedPluginNameForVolume(volumePluginName, volumeToMount.VolumeSpec), "overall_volume_mount", totalTimeTaken)
 
 		markVolMountedErr := actualStateOfWorld.MarkVolumeAsMounted(markOpts)
 		if markVolMountedErr != nil {