Add metrics for scheduling and pulling

Author: LEDfan

src/main/java/eu/openanalytics/containerproxy/backend/kubernetes/KubernetesBackend.java

@@ -44,11 +44,13 @@
 import io.fabric8.kubernetes.api.model.ContainerPortBuilder;
 import io.fabric8.kubernetes.api.model.EnvVar;
 import io.fabric8.kubernetes.api.model.EnvVarSourceBuilder;
+import io.fabric8.kubernetes.api.model.Event;
 import io.fabric8.kubernetes.api.model.GenericKubernetesResource;
 import io.fabric8.kubernetes.api.model.GenericKubernetesResourceList;
 import io.fabric8.kubernetes.api.model.HasMetadata;
 import io.fabric8.kubernetes.api.model.LocalObjectReference;
 import io.fabric8.kubernetes.api.model.ObjectMetaBuilder;
+import io.fabric8.kubernetes.api.model.ObjectReferenceBuilder;
 import io.fabric8.kubernetes.api.model.Pod;
 import io.fabric8.kubernetes.api.model.PodBuilder;
 import io.fabric8.kubernetes.api.model.ServiceBuilder;
@@ -87,6 +89,9 @@
 import java.nio.file.Files;
 import java.nio.file.Path;
 import java.nio.file.Paths;
+import java.time.LocalDateTime;
+import java.time.OffsetDateTime;
+import java.time.ZoneId;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.Collections;
@@ -312,6 +317,39 @@ protected Container startContainer(ContainerSpec spec, Proxy proxy) throws Excep
 		proxyStatusService.containerStarted(proxy, container);
 		Pod pod = kubeClient.resource(startedPod).fromServer().get();
 
+		// TODO check k8s compatibility
+		List<Event> events = kubeClient.v1().events().withInvolvedObject(new ObjectReferenceBuilder()
+				.withKind("Pod")
+				.withName(pod.getMetadata().getName())
+				.withNamespace(pod.getMetadata().getNamespace())
+				.build()).list().getItems();
+
+		LocalDateTime pullingTime = null;
+		LocalDateTime pulledTime = null;
+		LocalDateTime scheduledTime = null;
+
+		for (Event event : events) {
+			if (event.getCount() != null && event.getCount() >  1) {
+				// ignore events which happened multiple time as we are unable to properly process them
+				continue;
+			}
+			if (event.getReason().equalsIgnoreCase("Pulling")) {
+				pullingTime = OffsetDateTime.parse(event.getLastTimestamp()).atZoneSameInstant(ZoneId.systemDefault()).toLocalDateTime();
+			} else if (event.getReason().equalsIgnoreCase("Pulled")) {
+				pulledTime = OffsetDateTime.parse(event.getLastTimestamp()).atZoneSameInstant(ZoneId.systemDefault()).toLocalDateTime();
+			} else if (event.getReason().equalsIgnoreCase("Scheduled")) {
+				scheduledTime = OffsetDateTime.parse(event.getEventTime().getTime()).atZoneSameInstant(ZoneId.systemDefault()).toLocalDateTime();
+			}
+		}
+
+		if (pullingTime != null && pulledTime != null) {
+			proxyStatusService.imagePulled(proxy, container, pullingTime, pulledTime);
+		}
+
+		if (scheduledTime != null) {
+			proxyStatusService.containerScheduled(proxy, container,  scheduledTime);
+		}
+
 		Service service = null;
 		if (isUseInternalNetwork()) {
 			// If SP runs inside the cluster, it can access pods directly and doesn't need any port publishing service.

src/main/java/eu/openanalytics/containerproxy/model/runtime/ProxyStartupLog.java

@@ -47,6 +47,14 @@ public Map<Integer, StartupStep> getStartApplication() {
         return startApplication;
     }
 
+    public Map<Integer, StartupStep> getPullImage() {
+        return pullImage;
+    }
+
+    public Map<Integer, StartupStep> getScheduleContainer() {
+        return scheduleContainer;
+    }
+
     public static class StartupStep {
 
         private LocalDateTime startTime = null;
@@ -69,6 +77,15 @@ public void stepSucceeded() {
             state = StartupStepState.SUCCESS;
         }
 
+        public void stepSucceeded(LocalDateTime startTime, LocalDateTime endTime) {
+            if (state != StartupStepState.NOT_EXECUTED || startTime == null || endTime == null) {
+                throw new IllegalStateException("Cannot start step if it's already started!");
+            }
+            this.startTime = startTime;
+            this.endTime = endTime;
+            state = StartupStepState.SUCCESS;
+        }
+
         public void stepFailed() {
             if (state != StartupStepState.STARTED) {
                 throw new IllegalStateException("Cannot finish (with failure) step if it is not yet started or already completed");

src/main/java/eu/openanalytics/containerproxy/service/ProxyStatusService.java

@@ -5,6 +5,7 @@
 import eu.openanalytics.containerproxy.model.runtime.ProxyStartupLog;
 import org.springframework.stereotype.Service;
 
+import java.time.LocalDateTime;
 import java.util.Map;
 import java.util.concurrent.ConcurrentHashMap;
 
@@ -29,6 +30,22 @@ public void containerStarting(Proxy proxy, Container container) {
         startupLog.get(proxy.getId()).getStartContainer(container.getIndex()).stepStarted();
     }
 
+    /**
+     * Step 2.1: schedule container
+     */
+    public void containerScheduled(Proxy proxy, Container container, LocalDateTime scheduledTime) {
+        startupLog.get(proxy.getId()).getScheduleContainer(container.getIndex()).stepSucceeded(
+                startupLog.get(proxy.getId()).getStartContainer(container.getIndex()).getStartTime(),
+                scheduledTime);
+    }
+
+    /**
+     * Step 2.2: pull image
+     */
+    public void imagePulled(Proxy proxy, Container container, LocalDateTime pullingTime, LocalDateTime pulledTime) {
+        startupLog.get(proxy.getId()).getPullImage(container.getIndex()).stepSucceeded(pullingTime, pulledTime);
+    }
+
     /**
      * Step 3: container has been started and application is starting up
      */

src/main/java/eu/openanalytics/containerproxy/stat/impl/Micrometer.java

@@ -100,6 +100,8 @@ public void init() {
             registry.gauge("absolute_apps_running", Tags.of("spec.id", spec.getId()), proxyCounter, wrapHandleNull(ProxyCounter::getProxyCount));
             registry.timer("startupTime", "spec.id", spec.getId());
             for (ContainerSpec containerSpec : spec.getContainerSpecs()) {
+                registry.timer("imagePullTime", "spec.id", spec.getId(), "container.idx", containerSpec.getIndex().toString());
+                registry.timer("containerScheduleTime", "spec.id", spec.getId(), "container.idx", containerSpec.getIndex().toString());
                 registry.timer("containerStartupTime", "spec.id", spec.getId(), "container.idx", containerSpec.getIndex().toString());
                 registry.timer("applicationStartupTime", "spec.id", spec.getId(), "container.idx", containerSpec.getIndex().toString());
             }
@@ -137,6 +139,18 @@ public void onProxyStartEvent(ProxyStartEvent event) {
             registry.timer("startupTime", "spec.id", event.getSpecId()).record(d);
         });
 
+        startupLog.getPullImage().forEach((idx, step) -> {
+            step.getStepDuration().ifPresent((d) -> {
+                registry.timer("imagePullTime", "spec.id", event.getSpecId(), "container.idx", idx.toString()).record(d);
+            });
+        });
+
+        startupLog.getScheduleContainer().forEach((idx, step) -> {
+            step.getStepDuration().ifPresent((d) -> {
+                registry.timer("containerScheduleTime", "spec.id", event.getSpecId(), "container.idx", idx.toString()).record(d);
+            });
+        });
+
         startupLog.getStartContainer().forEach((idx, step) -> {
             step.getStepDuration().ifPresent((d) -> {
                 registry.timer("containerStartupTime", "spec.id", event.getSpecId(), "container.idx", idx.toString()).record(d);
@@ -149,6 +163,7 @@ public void onProxyStartEvent(ProxyStartEvent event) {
             });
         });
 
+
     }
 
     @EventListener