Adding container_start_duration metric for container multi-container mode.

Including the time when a container start request is
received and the time it is completed in the
ContainerStartedEvent proto message.

PiperOrigin-RevId: 495390114

pkg/sentry/control/BUILD

@@ -6,6 +6,9 @@ proto_library(
     name = "control",
     srcs = ["control.proto"],
     visibility = ["//visibility:public"],
+    deps = [
+        "@com_google_protobuf//:timestamp_proto",
+    ],
 )
 
 go_library(
@@ -50,6 +53,7 @@ go_library(
         "//pkg/tcpip/link/sniffer",
         "//pkg/urpc",
         "//pkg/usermem",
+        "@org_golang_google_protobuf//types/known/timestamppb",
         "@org_golang_x_sys//unix:go_default_library",
     ],
 )

pkg/sentry/control/control.proto

@@ -16,6 +16,8 @@ syntax = "proto3";
 
 package gvisor;
 
+import "google/protobuf/timestamp.proto";
+
 // ControlConfig configures the permission of controls.
 message ControlConfig {
   // Names for individual control URPC service objects.
@@ -41,9 +43,13 @@ message ControlConfig {
 }
 
 // ContainerStartedEvent is emitted when a container starts.
+// It also keeps a track of the time elapsed when a container
+// start request is received and the container actually starts.
 message ContainerStartedEvent {
   bool started = 1;
   string container_id = 2;
+  google.protobuf.Timestamp request_received = 3;
+  google.protobuf.Timestamp request_completed = 4;
 }
 
 // ContainerExitEvent is emitted when a container's init task exits. Duplicate

pkg/sentry/control/lifecycle.go

@@ -17,7 +17,9 @@ package control
 import (
 	"encoding/json"
 	"fmt"
+	"time"
 
+	"google.golang.org/protobuf/types/known/timestamppb"
 	"gvisor.dev/gvisor/pkg/abi/linux"
 	"gvisor.dev/gvisor/pkg/eventchannel"
 	"gvisor.dev/gvisor/pkg/fd"
@@ -183,6 +185,11 @@ func (l *Lifecycle) updateContainerState(containerID string, newState containerS
 
 // StartContainer will start a new container in the sandbox.
 func (l *Lifecycle) StartContainer(args *StartContainerArgs, _ *uint32) error {
+	timeRequested := time.Now()
+	timeRequestReceived := &timestamppb.Timestamp{
+		Seconds: timeRequested.Unix(),
+		Nanos:   int32(timeRequested.Nanosecond()),
+	}
 	log.Infof("StartContainer: %v", args)
 	if len(args.Files) != len(args.DonatedFDs) {
 		return fmt.Errorf("FilePayload.Files and DonatedFDs must have same number of elements (%d != %d)", len(args.Files), len(args.DonatedFDs))
@@ -313,10 +320,6 @@ func (l *Lifecycle) StartContainer(args *StartContainerArgs, _ *uint32) error {
 	// Start the newly created process.
 	l.Kernel.StartProcess(tg)
 	log.Infof("Started the new container %v ", initArgs.ContainerID)
-	eventchannel.LogEmit(&pb.ContainerStartedEvent{
-		Started:     true,
-		ContainerId: initArgs.ContainerID,
-	})
 
 	if err := l.updateContainerState(initArgs.ContainerID, stateRunning); err != nil {
 		// Sanity check: shouldn't fail to update the state at this point.
@@ -324,6 +327,17 @@ func (l *Lifecycle) StartContainer(args *StartContainerArgs, _ *uint32) error {
 
 	}
 
+	timeRequestCompleted := time.Now()
+	eventchannel.LogEmit(&pb.ContainerStartedEvent{
+		Started:         true,
+		ContainerId:     initArgs.ContainerID,
+		RequestReceived: timeRequestReceived,
+		RequestCompleted: &timestamppb.Timestamp{
+			Seconds: timeRequestCompleted.Unix(),
+			Nanos:   int32(timeRequestCompleted.Nanosecond()),
+		},
+	})
+
 	// TODO(b/251490950): reap thread needs to synchronize with Save, so the
 	// container state update doesn't race with state serialization.
 	go l.reap(initArgs.ContainerID, tg) // S/R-SAFE: see above.