From 054ceab58d803df0c4910fa722138f0ed2d94701 Mon Sep 17 00:00:00 2001 From: Paco Xu Date: Wed, 10 Aug 2022 10:54:15 +0800 Subject: [PATCH 1/2] kubelet: make the image pull time more accurate in event Signed-off-by: Paco Xu --- pkg/kubelet/images/image_manager.go | 5 +---- pkg/kubelet/images/puller.go | 17 +++++++++++------ 2 files changed, 12 insertions(+), 10 deletions(-) diff --git a/pkg/kubelet/images/image_manager.go b/pkg/kubelet/images/image_manager.go index beed4249e5a..5bc391b1728 100644 --- a/pkg/kubelet/images/image_manager.go +++ b/pkg/kubelet/images/image_manager.go @@ -19,7 +19,6 @@ package images import ( "context" "fmt" - "time" dockerref "github.com/docker/distribution/reference" v1 "k8s.io/api/core/v1" @@ -150,7 +149,6 @@ func (m *imageManager) EnsureImageExists(ctx context.Context, pod *v1.Pod, conta } m.podPullingTimeRecorder.RecordImageStartedPulling(pod.UID) m.logIt(ref, v1.EventTypeNormal, events.PullingImage, logPrefix, fmt.Sprintf("Pulling image %q", container.Image), klog.Info) - startTime := time.Now() pullChan := make(chan pullResult) m.puller.pullImage(ctx, spec, pullSecrets, pullChan, podSandboxConfig) imagePullResult := <-pullChan @@ -164,8 +162,7 @@ func (m *imageManager) EnsureImageExists(ctx context.Context, pod *v1.Pod, conta return "", imagePullResult.err.Error(), ErrImagePull } - m.podPullingTimeRecorder.RecordImageFinishedPulling(pod.UID) - m.logIt(ref, v1.EventTypeNormal, events.PulledImage, logPrefix, fmt.Sprintf("Successfully pulled image %q in %v", container.Image, time.Since(startTime)), klog.Info) + m.logIt(ref, v1.EventTypeNormal, events.PulledImage, logPrefix, fmt.Sprintf("Successfully pulled image %q in %v", container.Image, imagePullResult.pullDuration), klog.Info) m.backOff.GC() return imagePullResult.imageRef, "", nil } diff --git a/pkg/kubelet/images/puller.go b/pkg/kubelet/images/puller.go index fe7e9fb042c..2f0bda92cb0 100644 --- a/pkg/kubelet/images/puller.go +++ b/pkg/kubelet/images/puller.go @@ -27,8 +27,9 @@ import ( ) type pullResult struct { - imageRef string - err error + imageRef string + err error + pullDuration time.Duration } type imagePuller interface { @@ -47,10 +48,12 @@ func newParallelImagePuller(imageService kubecontainer.ImageService) imagePuller func (pip *parallelImagePuller) pullImage(ctx context.Context, spec kubecontainer.ImageSpec, pullSecrets []v1.Secret, pullChan chan<- pullResult, podSandboxConfig *runtimeapi.PodSandboxConfig) { go func() { + startTime := time.Now() imageRef, err := pip.imageService.PullImage(ctx, spec, pullSecrets, podSandboxConfig) pullChan <- pullResult{ - imageRef: imageRef, - err: err, + imageRef: imageRef, + err: err, + pullDuration: time.Since(startTime), } }() } @@ -89,10 +92,12 @@ func (sip *serialImagePuller) pullImage(ctx context.Context, spec kubecontainer. 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) pullRequest.pullChan <- pullResult{ - imageRef: imageRef, - err: err, + imageRef: imageRef, + err: err, + pullDuration: time.Since(startTime), } } } From 41902853fd1a55cd59ff9b44a11cb2c34a0269de Mon Sep 17 00:00:00 2001 From: Paco Xu Date: Mon, 22 Aug 2022 10:47:27 +0800 Subject: [PATCH 2/2] image pull event include duration with waiting Signed-off-by: Paco Xu --- pkg/kubelet/images/image_manager.go | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/pkg/kubelet/images/image_manager.go b/pkg/kubelet/images/image_manager.go index 5bc391b1728..3fbec1f2b56 100644 --- a/pkg/kubelet/images/image_manager.go +++ b/pkg/kubelet/images/image_manager.go @@ -19,6 +19,7 @@ package images import ( "context" "fmt" + "time" dockerref "github.com/docker/distribution/reference" v1 "k8s.io/api/core/v1" @@ -149,6 +150,7 @@ func (m *imageManager) EnsureImageExists(ctx context.Context, pod *v1.Pod, conta } m.podPullingTimeRecorder.RecordImageStartedPulling(pod.UID) m.logIt(ref, v1.EventTypeNormal, events.PullingImage, logPrefix, fmt.Sprintf("Pulling image %q", container.Image), klog.Info) + startTime := time.Now() pullChan := make(chan pullResult) m.puller.pullImage(ctx, spec, pullSecrets, pullChan, podSandboxConfig) imagePullResult := <-pullChan @@ -162,7 +164,7 @@ func (m *imageManager) EnsureImageExists(ctx context.Context, pod *v1.Pod, conta return "", imagePullResult.err.Error(), ErrImagePull } - m.logIt(ref, v1.EventTypeNormal, events.PulledImage, logPrefix, fmt.Sprintf("Successfully pulled image %q in %v", container.Image, imagePullResult.pullDuration), klog.Info) + m.logIt(ref, v1.EventTypeNormal, events.PulledImage, logPrefix, fmt.Sprintf("Successfully pulled image %q in %v (%v including waiting)", container.Image, imagePullResult.pullDuration, time.Since(startTime)), klog.Info) m.backOff.GC() return imagePullResult.imageRef, "", nil }