Merge pull request kubernetes#121719 from ruiwen-zhao/metric-size

Add image pull duration metric with bucketed image size

Author: k8s-ci-robot

pkg/kubelet/container/runtime.go

@@ -162,6 +162,8 @@ type ImageService interface {
 	ImageStats(ctx context.Context) (*ImageStats, error)
 	// ImageFsInfo returns a list of file systems for containers/images
 	ImageFsInfo(ctx context.Context) (*runtimeapi.ImageFsInfoResponse, error)
+	// GetImageSize returns the size of the image
+	GetImageSize(ctx context.Context, image ImageSpec) (uint64, error)
 }
 
 // Attacher interface allows to attach a container.

pkg/kubelet/container/testing/fake_runtime.go

@@ -362,6 +362,14 @@ func (f *FakeRuntime) GetImageRef(_ context.Context, image kubecontainer.ImageSp
 	return "", f.InspectErr
 }
 
+func (f *FakeRuntime) GetImageSize(_ context.Context, image kubecontainer.ImageSpec) (uint64, error) {
+	f.Lock()
+	defer f.Unlock()
+
+	f.CalledFunctions = append(f.CalledFunctions, "GetImageSize")
+	return 0, f.Err
+}
+
 func (f *FakeRuntime) ListImages(_ context.Context) ([]kubecontainer.Image, error) {
 	f.Lock()
 	defer f.Unlock()

pkg/kubelet/container/testing/runtime_mock.go

@@ -32,6 +32,7 @@ import (
 	crierrors "k8s.io/cri-api/pkg/errors"
 	kubecontainer "k8s.io/kubernetes/pkg/kubelet/container"
 	"k8s.io/kubernetes/pkg/kubelet/events"
+	"k8s.io/kubernetes/pkg/kubelet/metrics"
 	"k8s.io/kubernetes/pkg/util/parsers"
 )
 
@@ -166,8 +167,10 @@ func (m *imageManager) EnsureImageExists(ctx context.Context, pod *v1.Pod, conta
 		return "", msg, err
 	}
 	m.podPullingTimeRecorder.RecordImageFinishedPulling(pod.UID)
-	m.logIt(ref, v1.EventTypeNormal, events.PulledImage, logPrefix, fmt.Sprintf("Successfully pulled image %q in %v (%v including waiting)",
-		container.Image, imagePullResult.pullDuration.Truncate(time.Millisecond), time.Since(startTime).Truncate(time.Millisecond)), klog.Info)
+	imagePullDuration := time.Since(startTime).Truncate(time.Millisecond)
+	m.logIt(ref, v1.EventTypeNormal, events.PulledImage, logPrefix, fmt.Sprintf("Successfully pulled image %q in %v (%v including waiting). Image size: %v bytes.",
+		container.Image, imagePullResult.pullDuration.Truncate(time.Millisecond), imagePullDuration, imagePullResult.imageSize), klog.Info)
+	metrics.ImagePullDuration.WithLabelValues(metrics.GetImageSizeBucket(imagePullResult.imageSize)).Observe(imagePullDuration.Seconds())
 	m.backOff.GC()
 	return imagePullResult.imageRef, "", nil
 }

pkg/kubelet/images/image_manager.go

@@ -69,7 +69,7 @@ func pullerTestCases() []pullerTestCase {
 			qps:            0.0,
 			burst:          0,
 			expected: []pullerExpects{
-				{[]string{"GetImageRef", "PullImage"}, nil, true, true},
+				{[]string{"GetImageRef", "PullImage", "GetImageSize"}, nil, true, true},
 			}},
 
 		{ // image present, don't pull
@@ -94,9 +94,9 @@ func pullerTestCases() []pullerTestCase {
 			qps:        0.0,
 			burst:      0,
 			expected: []pullerExpects{
-				{[]string{"GetImageRef", "PullImage"}, nil, true, true},
-				{[]string{"GetImageRef", "PullImage"}, nil, true, true},
-				{[]string{"GetImageRef", "PullImage"}, nil, true, true},
+				{[]string{"GetImageRef", "PullImage", "GetImageSize"}, nil, true, true},
+				{[]string{"GetImageRef", "PullImage", "GetImageSize"}, nil, true, true},
+				{[]string{"GetImageRef", "PullImage", "GetImageSize"}, nil, true, true},
 			}},
 		// missing image, error PullNever
 		{containerImage: "missing_image",
@@ -149,9 +149,9 @@ func pullerTestCases() []pullerTestCase {
 			qps:        400.0,
 			burst:      600,
 			expected: []pullerExpects{
-				{[]string{"GetImageRef", "PullImage"}, nil, true, true},
-				{[]string{"GetImageRef", "PullImage"}, nil, true, true},
-				{[]string{"GetImageRef", "PullImage"}, nil, true, true},
+				{[]string{"GetImageRef", "PullImage", "GetImageSize"}, nil, true, true},
+				{[]string{"GetImageRef", "PullImage", "GetImageSize"}, nil, true, true},
+				{[]string{"GetImageRef", "PullImage", "GetImageSize"}, nil, true, true},
 			}},
 		// image present, non-zero qps, try to pull when qps exceeded
 		{containerImage: "present_image",
@@ -356,7 +356,7 @@ func TestPullAndListImageWithPodAnnotations(t *testing.T) {
 		inspectErr:     nil,
 		pullerErr:      nil,
 		expected: []pullerExpects{
-			{[]string{"GetImageRef", "PullImage"}, nil, true, true},
+			{[]string{"GetImageRef", "PullImage", "GetImageSize"}, nil, true, true},
 		}}
 
 	useSerializedEnv := true
@@ -412,7 +412,7 @@ func TestPullAndListImageWithRuntimeHandlerInImageCriAPIFeatureGate(t *testing.T
 		inspectErr:     nil,
 		pullerErr:      nil,
 		expected: []pullerExpects{
-			{[]string{"GetImageRef", "PullImage"}, nil, true, true},
+			{[]string{"GetImageRef", "PullImage", "GetImageSize"}, nil, true, true},
 		}}
 
 	useSerializedEnv := true

pkg/kubelet/images/image_manager_test.go

@@ -28,6 +28,7 @@ import (
 
 type pullResult struct {
 	imageRef     string
+	imageSize    uint64
 	err          error
 	pullDuration time.Duration
 }
@@ -58,8 +59,14 @@ func (pip *parallelImagePuller) pullImage(ctx context.Context, spec kubecontaine
 		}
 		startTime := time.Now()
 		imageRef, err := pip.imageService.PullImage(ctx, spec, pullSecrets, podSandboxConfig)
+		var size uint64
+		if err == nil && imageRef != "" {
+			// Getting the image size with best effort, ignoring the error.
+			size, _ = pip.imageService.GetImageSize(ctx, spec)
+		}
 		pullChan <- pullResult{
 			imageRef:     imageRef,
+			imageSize:    size,
 			err:          err,
 			pullDuration: time.Since(startTime),
 		}
@@ -102,9 +109,16 @@ func (sip *serialImagePuller) processImagePullRequests() {
 	for pullRequest := range sip.pullRequests {
 		startTime := time.Now()
 		imageRef, err := sip.imageService.PullImage(pullRequest.ctx, pullRequest.spec, pullRequest.pullSecrets, pullRequest.podSandboxConfig)
+		var size uint64
+		if err == nil && imageRef != "" {
+			// Getting the image size with best effort, ignoring the error.
+			size, _ = sip.imageService.GetImageSize(pullRequest.ctx, pullRequest.spec)
+		}
 		pullRequest.pullChan <- pullResult{
-			imageRef:     imageRef,
-			err:          err,
+			imageRef:  imageRef,
+			imageSize: size,
+			err:       err,
+			// Note: pullDuration includes credential resolution and getting the image size.
 			pullDuration: time.Since(startTime),
 		}
 	}

pkg/kubelet/images/puller.go

@@ -96,6 +96,18 @@ func (m *kubeGenericRuntimeManager) GetImageRef(ctx context.Context, image kubec
 	return resp.Image.Id, nil
 }
 
+func (m *kubeGenericRuntimeManager) GetImageSize(ctx context.Context, image kubecontainer.ImageSpec) (uint64, error) {
+	resp, err := m.imageService.ImageStatus(ctx, toRuntimeAPIImageSpec(image), false)
+	if err != nil {
+		klog.ErrorS(err, "Failed to get image status", "image", image.Image)
+		return 0, err
+	}
+	if resp.Image == nil {
+		return 0, nil
+	}
+	return resp.Image.Size_, nil
+}
+
 // ListImages gets all images currently on the machine.
 func (m *kubeGenericRuntimeManager) ListImages(ctx context.Context) ([]kubecontainer.Image, error) {
 	var images []kubecontainer.Image

pkg/kubelet/kuberuntime/kuberuntime_image.go

@@ -149,6 +149,20 @@ func TestGetImageRef(t *testing.T) {
 	assert.Equal(t, image, imageRef)
 }
 
+func TestImageSize(t *testing.T) {
+	ctx := context.Background()
+	_, fakeImageService, fakeManager, err := createTestRuntimeManager()
+	assert.NoError(t, err)
+
+	const imageSize = uint64(64)
+	fakeImageService.SetFakeImageSize(imageSize)
+	image := "busybox"
+	fakeImageService.SetFakeImages([]string{image})
+	actualSize, err := fakeManager.GetImageSize(ctx, kubecontainer.ImageSpec{Image: image})
+	assert.NoError(t, err)
+	assert.Equal(t, imageSize, actualSize)
+}
+
 func TestGetImageRefImageNotAvailableLocally(t *testing.T) {
 	ctx := context.Background()
 	_, _, fakeManager, err := createTestRuntimeManager()

pkg/kubelet/kuberuntime/kuberuntime_image_test.go

@@ -70,6 +70,7 @@ const (
 	WorkingPodCountKey                 = "working_pods"
 	OrphanedRuntimePodTotalKey         = "orphaned_runtime_pods_total"
 	RestartedPodTotalKey               = "restarted_pods_total"
+	ImagePullDurationKey               = "image_pull_duration_seconds"
 
 	// Metrics keys of remote runtime operations
 	RuntimeOperationsKey         = "runtime_operations_total"
@@ -126,8 +127,30 @@ const (
 	EphemeralContainer = "ephemeral_container"
 )
 
+type imageSizeBucket struct {
+	lowerBoundInBytes uint64
+	label             string
+}
+
 var (
 	podStartupDurationBuckets = []float64{0.5, 1, 2, 3, 4, 5, 6, 8, 10, 20, 30, 45, 60, 120, 180, 240, 300, 360, 480, 600, 900, 1200, 1800, 2700, 3600}
+	imagePullDurationBuckets  = []float64{1, 5, 10, 20, 30, 60, 120, 180, 240, 300, 360, 480, 600, 900, 1200, 1800, 2700, 3600}
+	// imageSizeBuckets has the labels to be associated with image_pull_duration_seconds metric. For example, if the size of
+	// an image pulled is between 1GB and 5GB, the label will be "1GB-5GB".
+	imageSizeBuckets = []imageSizeBucket{
+		{0, "0-10MB"},
+		{10 * 1024 * 1024, "10MB-100MB"},
+		{100 * 1024 * 1024, "100MB-500MB"},
+		{500 * 1024 * 1024, "500MB-1GB"},
+		{1 * 1024 * 1024 * 1024, "1GB-5GB"},
+		{5 * 1024 * 1024 * 1024, "5GB-10GB"},
+		{10 * 1024 * 1024 * 1024, "10GB-20GB"},
+		{20 * 1024 * 1024 * 1024, "20GB-30GB"},
+		{30 * 1024 * 1024 * 1024, "30GB-40GB"},
+		{40 * 1024 * 1024 * 1024, "40GB-60GB"},
+		{60 * 1024 * 1024 * 1024, "60GB-100GB"},
+		{100 * 1024 * 1024 * 1024, "GT100GB"},
+	}
 )
 
 var (
@@ -822,6 +845,20 @@ var (
 			StabilityLevel: metrics.ALPHA,
 		},
 	)
+
+	// ImagePullDuration is a Histogram that tracks the duration (in seconds) it takes for an image to be pulled,
+	// including the time spent in the waiting queue of image puller.
+	// The metric is broken down by bucketed image size.
+	ImagePullDuration = metrics.NewHistogramVec(
+		&metrics.HistogramOpts{
+			Subsystem:      KubeletSubsystem,
+			Name:           ImagePullDurationKey,
+			Help:           "Duration in seconds to pull an image.",
+			Buckets:        imagePullDurationBuckets,
+			StabilityLevel: metrics.ALPHA,
+		},
+		[]string{"image_size_in_bytes"},
+	)
 )
 
 var registerMetrics sync.Once
@@ -835,6 +872,7 @@ func Register(collectors ...metrics.StableCollector) {
 		legacyregistry.MustRegister(PodStartDuration)
 		legacyregistry.MustRegister(PodStartSLIDuration)
 		legacyregistry.MustRegister(PodStartTotalDuration)
+		legacyregistry.MustRegister(ImagePullDuration)
 		legacyregistry.MustRegister(NodeStartupPreKubeletDuration)
 		legacyregistry.MustRegister(NodeStartupPreRegistrationDuration)
 		legacyregistry.MustRegister(NodeStartupRegistrationDuration)
@@ -921,3 +959,18 @@ func SinceInSeconds(start time.Time) float64 {
 func SetNodeName(name types.NodeName) {
 	NodeName.WithLabelValues(string(name)).Set(1)
 }
+
+func GetImageSizeBucket(sizeInBytes uint64) string {
+	if sizeInBytes == 0 {
+		return "N/A"
+	}
+
+	for i := len(imageSizeBuckets) - 1; i >= 0; i-- {
+		if sizeInBytes > imageSizeBuckets[i].lowerBoundInBytes {
+			return imageSizeBuckets[i].label
+		}
+	}
+
+	// return empty string when sizeInBytes is 0 (error getting image size)
+	return ""
+}

pkg/kubelet/metrics/metrics.go

@@ -0,0 +1,77 @@
+/*
+Copyright 2024 The Kubernetes Authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package metrics
+
+import (
+	"os"
+	"testing"
+
+	"k8s.io/component-base/metrics/testutil"
+)
+
+const imagePullDurationKey = "kubelet_" + ImagePullDurationKey
+
+func TestImagePullDurationMetric(t *testing.T) {
+	t.Run("register image pull duration", func(t *testing.T) {
+		Register()
+		defer clearMetrics()
+
+		// Pairs of image size in bytes and pull duration in seconds
+		dataPoints := [][]float64{
+			// 0 byets, 0 seconds
+			{0, 0},
+			// 5MB, 10 seconds
+			{5 * 1024 * 1024, 10},
+			// 15MB, 20 seconds
+			{15 * 1024 * 1024, 20},
+			// 500 MB, 200 seconds
+			{500 * 1024 * 1024, 200},
+			// 15 GB, 6000 seconds,
+			{15 * 1024 * 1024 * 1024, 6000},
+			// 200 GB, 10000 seconds
+			{200 * 1024 * 1024 * 1024, 10000},
+		}
+
+		for _, dp := range dataPoints {
+			imageSize := int64(dp[0])
+			duration := dp[1]
+			t.Log(imageSize, duration)
+			t.Log(GetImageSizeBucket(uint64(imageSize)))
+			ImagePullDuration.WithLabelValues(GetImageSizeBucket(uint64(imageSize))).Observe(duration)
+		}
+
+		wants, err := os.Open("testdata/image_pull_duration_metric")
+		defer func() {
+			if err := wants.Close(); err != nil {
+				t.Error(err)
+			}
+		}()
+
+		if err != nil {
+			t.Fatal(err)
+		}
+
+		if err := testutil.GatherAndCompare(GetGather(), wants, imagePullDurationKey); err != nil {
+			t.Error(err)
+		}
+
+	})
+}
+
+func clearMetrics() {
+	ImagePullDuration.Reset()
+}