Capture total mount/unmount operation time

pkg/kubelet/volumemanager/cache/actual_state_of_world.go

@@ -23,6 +23,7 @@ package cache
 import (
 	"fmt"
 	"sync"
+	"time"
 
 	"k8s.io/api/core/v1"
 	"k8s.io/apimachinery/pkg/types"
@@ -159,6 +160,8 @@ type ActualStateOfWorld interface {
 	// to the node. This list can be used to determine volumes that are either in-use
 	// or have a mount/unmount operation pending.
 	GetAttachedVolumes() []AttachedVolume
+
+	RecordVolumeUnmount(podName volumetypes.UniquePodName, volumeSpecName v1.UniqueVolumeName)
 }
 
 // MountedVolume represents a volume that has successfully been mounted to a pod.
@@ -306,6 +309,9 @@ type mountedPod struct {
 	// fsResizeRequired indicates the underlying volume has been successfully
 	// mounted to this pod but its size has been expanded after that.
 	fsResizeRequired bool
+
+	// Time at which unmount was requested
+	unmountRequestTime time.Time
 }
 
 func (asw *actualStateOfWorld) MarkVolumeAsAttached(
@@ -425,6 +431,19 @@ func (asw *actualStateOfWorld) addVolume(
 	return nil
 }
 
+func (asw *actualStateOfWorld) RecordVolumeUnmount(podName volumetypes.UniquePodName, volumeName v1.UniqueVolumeName) {
+	volumeObj, volumeExists := asw.attachedVolumes[volumeName]
+	if !volumeExists {
+		return
+	}
+	podObj, podExists := volumeObj.mountedPods[podName]
+	if !podExists {
+		return
+	}
+	podObj.unmountRequestTime = time.Now()
+	asw.attachedVolumes[volumeName].mountedPods[podName] = podObj
+}
+
 func (asw *actualStateOfWorld) AddPodToVolume(
 	podName volumetypes.UniquePodName,
 	podUID types.UID,
@@ -871,5 +890,6 @@ func getMountedVolume(
 			BlockVolumeMapper:   mountedPod.blockVolumeMapper,
 			VolumeGidValue:      mountedPod.volumeGidValue,
 			VolumeSpec:          mountedPod.volumeSpec,
+			UnmountRequestTime:  mountedPod.unmountRequestTime,
 			DeviceMountPath:     attachedVolume.deviceMountPath}}
 }

pkg/kubelet/volumemanager/cache/desired_state_of_world.go

@@ -23,6 +23,7 @@ package cache
 import (
 	"fmt"
 	"sync"
+	"time"
 
 	"k8s.io/api/core/v1"
 	"k8s.io/kubernetes/pkg/volume"
@@ -182,6 +183,9 @@ type podToMount struct {
 	// volume claim, this contains the volume.Spec.Name() of the persistent
 	// volume claim
 	outerVolumeSpecName string
+
+	// time at which mount was first requested
+	mountRequestTime time.Time
 }
 
 func (dsw *desiredStateOfWorld) AddPodToVolume(
@@ -239,11 +243,18 @@ func (dsw *desiredStateOfWorld) AddPodToVolume(
 	// Create new podToMount object. If it already exists, it is refreshed with
 	// updated values (this is required for volumes that require remounting on
 	// pod update, like Downward API volumes).
+	oldPodMount, ok := dsw.volumesToMount[volumeName].podsToMount[podName]
+	mountRequestTime := time.Now()
+	if ok {
+		mountRequestTime = oldPodMount.mountRequestTime
+	}
+
 	dsw.volumesToMount[volumeName].podsToMount[podName] = podToMount{
 		podName:             podName,
 		pod:                 pod,
 		volumeSpec:          volumeSpec,
 		outerVolumeSpecName: outerVolumeSpecName,
+		mountRequestTime:    mountRequestTime,
 	}
 	return volumeName, nil
 }
@@ -360,6 +371,7 @@ func (dsw *desiredStateOfWorld) GetVolumesToMount() []VolumeToMount {
 						PluginIsDeviceMountable: volumeObj.pluginIsDeviceMountable,
 						OuterVolumeSpecName:     podObj.outerVolumeSpecName,
 						VolumeGidValue:          volumeObj.volumeGidValue,
+						MountRequestTime:        podObj.mountRequestTime,
 						ReportedInUse:           volumeObj.reportedInUse}})
 		}
 	}

pkg/kubelet/volumemanager/populator/desired_state_of_world_populator.go

@@ -267,6 +267,7 @@ func (dswp *desiredStateOfWorldPopulator) findAndRemoveDeletedPods() {
 		dswp.desiredStateOfWorld.DeletePodFromVolume(
 			volumeToMount.PodName, volumeToMount.VolumeName)
 		dswp.deleteProcessedPod(volumeToMount.PodName)
+		dswp.actualStateOfWorld.RecordVolumeUnmount(volumeToMount.PodName, volumeToMount.VolumeName)
 	}
 }
 

pkg/volume/util/metrics.go

@@ -65,6 +65,37 @@ func OperationCompleteHook(plugin, operationName string) func(*error) {
 	return opComplete
 }
 
+type OperationRequestTime interface {
+	GetOperationRequestTime() time.Time
+}
+
+// CaptureTotalOpTime function captures total time taken by an operation and time taken by particular volume operation
+// once started. For example:
+//	- volume_mount : metric captures time taken by mount operation once volumemanager has actually started the
+//	   mount process.
+//	- total_volume_mount - metric captures total time taken for entire mount operation once it enters desired
+//	  state of the world. This time could include waiting for volume to be attached, node to be updated and everything.
+func CaptureTotalOpTime(opData OperationRequestTime, plugin, operationName string) func(*error) {
+	requestTime := time.Now()
+	opComplete := func(err *error) {
+		timeTaken := time.Since(requestTime).Seconds()
+		// Create metric with operation name and plugin name
+		if *err != nil {
+			storageOperationErrorMetric.WithLabelValues(plugin, operationName).Inc()
+		} else {
+			totalOperationName := "total_" + operationName
+			totalTimeTaken := time.Since(opData.GetOperationRequestTime()).Seconds()
+
+			// record same operation's total time taken
+			storageOperationMetric.WithLabelValues(plugin, totalOperationName).Observe(totalTimeTaken)
+
+			// record just time taken for operation to run once started
+			storageOperationMetric.WithLabelValues(plugin, operationName).Observe(timeTaken)
+		}
+	}
+	return opComplete
+}
+
 // GetFullQualifiedPluginNameForVolume returns full qualified plugin name for
 // given volume. For CSI plugin, it appends plugin driver name at the end of
 // plugin name, e.g. kubernetes.io/csi:csi-hostpath. It helps to distinguish

pkg/volume/util/operationexecutor/operation_executor.go

@@ -349,8 +349,14 @@ type VolumeToMount struct {
 	// ReportedInUse indicates that the volume was successfully added to the
 	// VolumesInUse field in the node's status.
 	ReportedInUse bool
+
+	// time at which volume was requested to be mounted
+	MountRequestTime time.Time
 }
 
+var _ util.OperationRequestTime = &VolumeToMount{}
+var _ util.OperationRequestTime = &MountedVolume{}
+
 // GenerateMsgDetailed returns detailed msgs for volumes to mount
 func (volume *VolumeToMount) GenerateMsgDetailed(prefixMsg, suffixMsg string) (detailedMsg string) {
 	detailedStr := fmt.Sprintf("(UniqueName: %q) pod %q (UID: %q)", volume.VolumeName, volume.Pod.Name, volume.Pod.UID)
@@ -371,6 +377,10 @@ func (volume *VolumeToMount) GenerateMsg(prefixMsg, suffixMsg string) (simpleMsg
 	return generateVolumeMsg(prefixMsg, suffixMsg, volumeSpecName, detailedStr)
 }
 
+func (volume VolumeToMount) GetOperationRequestTime() time.Time {
+	return volume.MountRequestTime
+}
+
 // GenerateErrorDetailed returns detailed errors for volumes to mount
 func (volume *VolumeToMount) GenerateErrorDetailed(prefixMsg string, err error) (detailedErr error) {
 	return fmt.Errorf(volume.GenerateMsgDetailed(prefixMsg, errSuffix(err)))
@@ -556,6 +566,9 @@ type MountedVolume struct {
 	// DeviceMountPath contains the path on the node where the device should
 	// be mounted after it is attached.
 	DeviceMountPath string
+
+	// contains time at which volume was requested to be unmounted
+	UnmountRequestTime time.Time
 }
 
 // GenerateMsgDetailed returns detailed msgs for mounted volumes
@@ -581,6 +594,11 @@ func (volume *MountedVolume) GenerateError(prefixMsg string, err error) (simpleE
 	return fmt.Errorf(simpleMsg), fmt.Errorf(detailedMsg)
 }
 
+// GetOperationRequestTime returns time at which unmount was requested.
+func (volume MountedVolume) GetOperationRequestTime() time.Time {
+	return volume.UnmountRequestTime
+}
+
 type operationExecutor struct {
 	// pendingOperations keeps track of pending attach and detach operations so
 	// multiple operations are not started on the same volume

pkg/volume/util/operationexecutor/operation_generator.go

@@ -706,10 +706,12 @@ func (og *operationGenerator) GenerateMountVolumeFunc(
 		}
 	}
 
+	qualifiedPluginName := util.GetFullQualifiedPluginNameForVolume(volumePluginName, volumeToMount.VolumeSpec)
+
 	return volumetypes.GeneratedOperations{
 		OperationFunc:     mountVolumeFunc,
 		EventRecorderFunc: eventRecorderFunc,
-		CompleteFunc:      util.OperationCompleteHook(util.GetFullQualifiedPluginNameForVolume(volumePluginName, volumeToMount.VolumeSpec), "volume_mount"),
+		CompleteFunc:      util.CaptureTotalOpTime(volumeToMount, qualifiedPluginName, "volume_mount"),
 	}
 }
 
@@ -832,10 +834,11 @@ func (og *operationGenerator) GenerateUnmountVolumeFunc(
 
 		return nil, nil
 	}
+	qualifiedPluginName := util.GetFullQualifiedPluginNameForVolume(volumePlugin.GetPluginName(), volumeToUnmount.VolumeSpec)
 
 	return volumetypes.GeneratedOperations{
 		OperationFunc:     unmountVolumeFunc,
-		CompleteFunc:      util.OperationCompleteHook(util.GetFullQualifiedPluginNameForVolume(volumePlugin.GetPluginName(), volumeToUnmount.VolumeSpec), "volume_unmount"),
+		CompleteFunc:      util.CaptureTotalOpTime(volumeToUnmount, qualifiedPluginName, "volume_unmount"),
 		EventRecorderFunc: nil, // nil because we do not want to generate event on error
 	}, nil
 }