starttime: Get process start time from /proc/self/status if possible.

This more accurately determines when the process was started, since it is not
affected by the overhead of running linked library `init` code and
initializing `runsc`'s CLI code.

Additionally, when `runsc` execs itself, preserve this time across the exec.

Also move the code that determines the start time earlier in the file.

PiperOrigin-RevId: 752025678

Author: EtiennePerot

pkg/timing/timing.go

@@ -103,16 +103,24 @@ func (s *Timeline) Reached(name string) {
 	if s == nil {
 		return
 	}
-	now := time.Now()
+	s.ReachedAt(name, time.Now())
+}
+
+// ReachedAt records a new midpoint on the root Timeline of the Timer with
+// the given timestamp.
+func (s *Timeline) ReachedAt(name string, when time.Time) {
+	if s == nil {
+		return
+	}
 	s.midpoints = append(s.midpoints, MidPoint{
-		when: now,
+		when: when,
 		name: name,
 	})
 	if log.IsLogging(log.Debug) {
 		if s.timer != nil {
-			log.Debugf("Timer for %s: Timeline %s reached midpoint %s at %s (unix nanos: %d)", s.timer.root.name, s.fullName, name, now.Format(fullTimestampFormat), now.UnixNano())
+			log.Debugf("Timer for %s: Timeline %s reached midpoint %s at %s (unix nanos: %d)", s.timer.root.name, s.fullName, name, when.Format(fullTimestampFormat), when.UnixNano())
 		} else {
-			log.Debugf("Orphaned timeline %s reached midpoint %s at %s (unix nanos: %d)", s.name, name, now.Format(fullTimestampFormat), now.UnixNano())
+			log.Debugf("Orphaned timeline %s reached midpoint %s at %s (unix nanos: %d)", s.name, name, when.Format(fullTimestampFormat), when.UnixNano())
 		}
 	}
 }
@@ -432,6 +440,15 @@ func (t *Timer) Reached(name string) {
 	t.root.Reached(name)
 }
 
+// ReachedAt records a new midpoint on the root Timeline of the Timer with
+// the given timestamp.
+func (t *Timer) ReachedAt(name string, when time.Time) {
+	if t == nil {
+		return
+	}
+	t.root.ReachedAt(name, when)
+}
+
 // Fork creates a new Timeline that is a child of the root Timeline of this
 // Timer.
 // The returned Timeline is initially owned by the caller, but may be passed

runsc/cli/main.go

@@ -62,6 +62,9 @@ var (
 
 // Main is the main entrypoint.
 func Main() {
+	// Set the start time as soon as possible.
+	startTime := starttime.Get()
+
 	// Register all commands.
 	forEachCmd(subcommands.Register)
 
@@ -133,9 +136,6 @@ func Main() {
 	// case that does not occur.
 	_ = time.Local.String()
 
-	// Set the start time as soon as possible.
-	startTime := starttime.Get()
-
 	var emitters log.MultiEmitter
 	if *debugLogFD > -1 {
 		f := os.NewFile(uintptr(*debugLogFD), "debug log file")
@@ -197,6 +197,13 @@ func Main() {
 	log.Debugf("Page size: 0x%x (%d bytes)", os.Getpagesize(), os.Getpagesize())
 	log.Infof("Args: %v", os.Args)
 	conf.Log()
+	if log.IsLogging(log.Debug) {
+		if goStartTime := starttime.GoStartTime(); goStartTime.Equal(startTime) {
+			log.Debugf("Go started execution at %s. Could not measure process spawn time (no /proc/self/status?)", goStartTime.Format("15:04:05.000000"))
+		} else {
+			log.Debugf("runsc process spawned at %v, Go started execution at %s. Startup overhead: %v", startTime.Format("15:04:05.000000"), goStartTime.Format("15:04:05.000000"), goStartTime.Sub(startTime))
+		}
+	}
 	log.Infof(delimString)
 
 	if *coverageFD >= 0 {

runsc/cmd/BUILD

@@ -116,6 +116,7 @@ go_library(
         "//runsc/mitigate",
         "//runsc/profile",
         "//runsc/specutils",
+        "//runsc/starttime",
         "@com_github_google_subcommands//:go_default_library",
         "@com_github_moby_sys_capability//:go_default_library",
         "@com_github_opencontainers_runtime_spec//specs-go:go_default_library",

runsc/cmd/cmd.go

@@ -27,6 +27,7 @@ import (
 	"gvisor.dev/gvisor/pkg/fd"
 	"gvisor.dev/gvisor/pkg/log"
 	"gvisor.dev/gvisor/runsc/specutils"
+	"gvisor.dev/gvisor/runsc/starttime"
 )
 
 // intFlags can be used with int flags that appear multiple times. It supports
@@ -90,7 +91,7 @@ func setCapsAndCallSelf(args []string, caps *specs.LinuxCapabilities) error {
 	binPath := specutils.ExePath
 
 	log.Infof("Execve %q again, bye!", binPath)
-	err := unix.Exec(binPath, args, os.Environ())
+	err := unix.Exec(binPath, args, starttime.AppendEnviron(os.Environ()))
 	return fmt.Errorf("error executing %s: %v", binPath, err)
 }
 
@@ -116,6 +117,6 @@ func callSelfAsNobody(args []string) error {
 	binPath := specutils.ExePath
 
 	log.Infof("Execve %q again, bye!", binPath)
-	err := unix.Exec(binPath, args, os.Environ())
+	err := unix.Exec(binPath, args, starttime.AppendEnviron(os.Environ()))
 	return fmt.Errorf("error executing %s: %v", binPath, err)
 }

runsc/starttime/BUILD

@@ -11,4 +11,5 @@ go_library(
         "starttime.go",
     ],
     visibility = ["//runsc:__subpackages__"],
+    deps = ["//pkg/timing"],
 )

runsc/starttime/starttime.go

@@ -17,19 +17,84 @@
 package starttime
 
 import (
+	"fmt"
+	"os"
+	"strconv"
+	"strings"
 	"sync"
 	"time"
+
+	"gvisor.dev/gvisor/pkg/timing"
 )
 
 var (
-	setOnce   sync.Once
-	startTime time.Time
+	setOnce      sync.Once
+	processStart time.Time
+	goStartTime  time.Time
+	envStartTime time.Time
 )
 
-// Get returns the time the `runsc` command started.
+// envStartTimeKey is the environment variable that holds the time the `runsc`
+// command started. This is used to track the actual start time across
+// re-execs of `runsc`.
+const envStartTimeKey = "RUNSC_START_TIME_NANOS"
+
+// Get returns the time the `runsc` command started on a best-effort basis.
+// If the RUNSC_START_TIME_NANOS environment variable is set, it is used.
+// Otherwise, it tries to get the time from /proc/self/status.
+// If neither is available, it returns the time the function was first called.
 func Get() time.Time {
 	setOnce.Do(func() {
-		startTime = time.Now()
+		goStartTime = time.Now()
+		if startTimeStr, found := os.LookupEnv(envStartTimeKey); found {
+			if startTime, err := strconv.ParseInt(startTimeStr, 10, 64); err == nil {
+				envStartTime = time.Unix(0, startTime)
+				return // No need to check /proc/self/status.
+			}
+		}
+		if st, err := os.Stat("/proc/self/status"); err == nil {
+			processStart = st.ModTime()
+		}
 	})
-	return startTime
+	if !envStartTime.IsZero() {
+		return envStartTime
+	}
+	if !processStart.IsZero() {
+		return processStart
+	}
+	return goStartTime
+}
+
+// GoStartTime returns the time the `runsc` command's Go code started.
+func GoStartTime() time.Time {
+	Get()
+	return goStartTime
+}
+
+// Timer returns a Timer object that is rooted at `runsc` execution start.
+// If `runsc` was re-exec'd, this timer will have a midpoint called "re-exec"
+// that corresponds to the time of the re-exec.
+func Timer(name string) *timing.Timer {
+	timer := timing.New(name, Get())
+	if !envStartTime.IsZero() {
+		if !processStart.IsZero() {
+			timer.ReachedAt("re-exec", processStart)
+		} else {
+			timer.ReachedAt("re-exec", goStartTime)
+		}
+	}
+	return timer
+}
+
+// AppendEnviron appends the RUNSC_START_TIME_NANOS environment variable to
+// the given environment, if it is not already present. Otherwise, it is
+// preserved.
+func AppendEnviron(env []string) []string {
+	const envVarPrefix = envStartTimeKey + "="
+	for _, e := range env {
+		if strings.HasPrefix(e, envVarPrefix) {
+			return env
+		}
+	}
+	return append(env, fmt.Sprintf("%s=%d", envStartTimeKey, Get().UnixNano()))
 }

test/root/runsc_test.go

@@ -21,6 +21,7 @@ import (
 	"os"
 	"os/exec"
 	"path/filepath"
+	"regexp"
 	"strconv"
 	"strings"
 	"testing"
@@ -171,6 +172,7 @@ func TestSandboxProcessEnv(t *testing.T) {
 	if err != nil {
 		t.Fatal(err)
 	}
+	got = regexp.MustCompile("(^|\x00)RUNSC_START_TIME_NANOS=\\d+\x00").ReplaceAll(got, []byte("$1"))
 	if len(got) != 0 && string(got) != "GLIBC_TUNABLES=glibc.pthread.rseq=0\x00" {
 		t.Errorf("sandbox process's environment is not empty: got %s (%v)", string(got), got)
 	}