diff --git a/pkg/kubelet/config/config.go b/pkg/kubelet/config/config.go index f82ba39fa48..7466333eeed 100644 --- a/pkg/kubelet/config/config.go +++ b/pkg/kubelet/config/config.go @@ -26,6 +26,7 @@ import ( "github.com/GoogleCloudPlatform/kubernetes/pkg/client/record" "github.com/GoogleCloudPlatform/kubernetes/pkg/kubelet" kubecontainer "github.com/GoogleCloudPlatform/kubernetes/pkg/kubelet/container" + kubeletTypes "github.com/GoogleCloudPlatform/kubernetes/pkg/kubelet/types" "github.com/GoogleCloudPlatform/kubernetes/pkg/util" "github.com/GoogleCloudPlatform/kubernetes/pkg/util/config" utilerrors "github.com/GoogleCloudPlatform/kubernetes/pkg/util/errors" @@ -183,6 +184,11 @@ func (s *podStorage) Merge(source string, change interface{}) error { return nil } +// recordFirstSeenTime records the first seen time of this pod. +func recordFirstSeenTime(pod *api.Pod) { + pod.Annotations[kubelet.ConfigFirstSeenAnnotationKey] = kubeletTypes.NewTimestamp().GetString() +} + func (s *podStorage) merge(source string, change interface{}) (adds, updates, deletes *kubelet.PodUpdate) { s.podLock.Lock() defer s.podLock.Unlock() @@ -223,6 +229,7 @@ func (s *podStorage) merge(source string, change interface{}) (adds, updates, de ref.Annotations = make(map[string]string) } ref.Annotations[kubelet.ConfigSourceAnnotationKey] = source + recordFirstSeenTime(ref) pods[name] = ref adds.Pods = append(adds.Pods, ref) } @@ -265,6 +272,7 @@ func (s *podStorage) merge(source string, change interface{}) (adds, updates, de ref.Annotations = make(map[string]string) } ref.Annotations[kubelet.ConfigSourceAnnotationKey] = source + recordFirstSeenTime(ref) pods[name] = ref adds.Pods = append(adds.Pods, ref) } diff --git a/pkg/kubelet/config/config_test.go b/pkg/kubelet/config/config_test.go index 9fe1fb860f9..d397bcd374d 100644 --- a/pkg/kubelet/config/config_test.go +++ b/pkg/kubelet/config/config_test.go @@ -91,6 +91,14 @@ func expectPodUpdate(t *testing.T, ch <-chan kubelet.PodUpdate, expected ...kube for i := range expected { update := <-ch sort.Sort(sortedPods(update.Pods)) + // Clear the annotation field before the comparision. + // TODO: consider mock out recordFirstSeen in config.go + for _, pod := range update.Pods { + delete(pod.Annotations, kubelet.ConfigFirstSeenAnnotationKey) + } + for _, pod := range expected[i].Pods { + delete(pod.Annotations, kubelet.ConfigFirstSeenAnnotationKey) + } if !api.Semantic.DeepEqual(expected[i], update) { t.Fatalf("Expected %#v, Got %#v", expected[i], update) } diff --git a/pkg/kubelet/kubelet.go b/pkg/kubelet/kubelet.go index bb39740833d..a2ed8ffc273 100644 --- a/pkg/kubelet/kubelet.go +++ b/pkg/kubelet/kubelet.go @@ -1098,6 +1098,12 @@ func (kl *Kubelet) syncPod(pod *api.Pod, mirrorPod *api.Pod, runningPod kubecont podFullName := kubecontainer.GetPodFullName(pod) uid := pod.UID start := time.Now() + var firstSeenTime time.Time + if firstSeenTimeStr, ok := pod.Annotations[ConfigFirstSeenAnnotationKey]; !ok { + glog.V(3).Infof("First seen time not recorded for pod %q", pod.UID) + } else { + firstSeenTime = kubeletTypes.ConvertToTimestamp(firstSeenTimeStr).Get() + } // Before returning, regenerate status and store it in the cache. defer func() { @@ -1115,9 +1121,9 @@ func (kl *Kubelet) syncPod(pod *api.Pod, mirrorPod *api.Pod, runningPod kubecont podToUpdate = mirrorPod } existingStatus, ok := kl.statusManager.GetPodStatus(podFullName) - if !ok || existingStatus.Phase == api.PodPending && status.Phase == api.PodRunning { - // TODO: Check the pod annotation instead of using `start` - metrics.PodStartLatency.Observe(metrics.SinceInMicroseconds(start)) + if !ok || existingStatus.Phase == api.PodPending && status.Phase == api.PodRunning && + !firstSeenTime.IsZero() { + metrics.PodStartLatency.Observe(metrics.SinceInMicroseconds(firstSeenTime)) } kl.statusManager.SetPodStatus(podToUpdate, status) } @@ -1175,6 +1181,12 @@ func (kl *Kubelet) syncPod(pod *api.Pod, mirrorPod *api.Pod, runningPod kubecont var podStatus api.PodStatus if updateType == SyncPodCreate { + // This is the first time we are syncing the pod. Record the latency + // since kubelet first saw the pod if firstSeenTime is set. + if !firstSeenTime.IsZero() { + metrics.PodWorkerStartLatency.Observe(metrics.SinceInMicroseconds(firstSeenTime)) + } + podStatus = pod.Status podStatus.StartTime = &util.Time{start} kl.statusManager.SetPodStatus(pod, podStatus) diff --git a/pkg/kubelet/metrics/metrics.go b/pkg/kubelet/metrics/metrics.go index 06eb2330998..d703ddd46b9 100644 --- a/pkg/kubelet/metrics/metrics.go +++ b/pkg/kubelet/metrics/metrics.go @@ -34,6 +34,7 @@ const ( ContainerManagerOperationsKey = "container_manager_latency_microseconds" DockerOperationsKey = "docker_operations_latency_microseconds" DockerErrorsKey = "docker_errors" + PodWorkerStartLatencyKey = "pod_worker_start_latency_microseconds" ) var ( @@ -81,6 +82,13 @@ var ( }, []string{"operation_type"}, ) + PodWorkerStartLatency = prometheus.NewSummary( + prometheus.SummaryOpts{ + Subsystem: KubeletSubsystem, + Name: PodWorkerStartLatencyKey, + Help: "Latency in microseconds from seeing a pod to starting a worker.", + }, + ) DockerOperationsLatency = prometheus.NewSummaryVec( prometheus.SummaryOpts{ Subsystem: KubeletSubsystem, @@ -111,6 +119,7 @@ func Register(containerCache kubecontainer.RuntimeCache) { prometheus.MustRegister(DockerOperationsLatency) prometheus.MustRegister(ContainerManagerLatency) prometheus.MustRegister(SyncPodsLatency) + prometheus.MustRegister(PodWorkerStartLatency) prometheus.MustRegister(ContainersPerPodCount) prometheus.MustRegister(DockerErrors) prometheus.MustRegister(newPodAndContainerCollector(containerCache)) diff --git a/pkg/kubelet/types.go b/pkg/kubelet/types.go index 1f28c5c2ff2..c4a7c50b39d 100644 --- a/pkg/kubelet/types.go +++ b/pkg/kubelet/types.go @@ -24,6 +24,7 @@ import ( const ConfigSourceAnnotationKey = "kubernetes.io/config.source" const ConfigMirrorAnnotationKey = "kubernetes.io/config.mirror" +const ConfigFirstSeenAnnotationKey = "kubernetes.io/config.seen" // PodOperation defines what changes will be made on a pod configuration. type PodOperation int diff --git a/pkg/kubelet/types/types.go b/pkg/kubelet/types/types.go index e4bd4c15cf0..172c84ae1ab 100644 --- a/pkg/kubelet/types/types.go +++ b/pkg/kubelet/types/types.go @@ -16,7 +16,10 @@ limitations under the License. package types -import "net/http" +import ( + "net/http" + "time" +) // DockerID is an ID of docker container. It is a type to make it clear when we're working with docker container Ids type DockerID string @@ -24,3 +27,32 @@ type DockerID string type HttpGetter interface { Get(url string) (*http.Response, error) } + +// Timestamp wraps around time.Time and offers utilities to format and parse +// the time using RFC3339Nano +type Timestamp struct { + time time.Time +} + +// NewTimestamp returns a Timestamp object using the current time. +func NewTimestamp() *Timestamp { + return &Timestamp{time.Now()} +} + +// ConvertToTimestamp takes a string, parses it using the RFC3339Nano layout, +// and converts it to a Timestamp object. +func ConvertToTimestamp(timeString string) *Timestamp { + parsed, _ := time.Parse(time.RFC3339Nano, timeString) + return &Timestamp{parsed} +} + +// Get returns the time as time.Time. +func (t *Timestamp) Get() time.Time { + return t.time +} + +// GetString returns the time in the string format using the RFC3339Nano +// layout. +func (t *Timestamp) GetString() string { + return t.time.Format(time.RFC3339Nano) +}