Measure and report the time taken during the sandbox restore process.

PiperOrigin-RevId: 758919824

Author: EtiennePerot

pkg/sentry/kernel/BUILD

@@ -382,6 +382,7 @@ go_library(
         "//pkg/syserr",
         "//pkg/tcpip",
         "//pkg/tcpip/stack",
+        "//pkg/timing",
         "//pkg/usermem",
         "//pkg/waiter",
         "@org_golang_google_protobuf//proto:go_default_library",

pkg/sentry/kernel/kernel_restore.go

@@ -27,6 +27,7 @@ import (
 	"gvisor.dev/gvisor/pkg/sentry/pgalloc"
 	"gvisor.dev/gvisor/pkg/state"
 	"gvisor.dev/gvisor/pkg/sync"
+	"gvisor.dev/gvisor/pkg/timing"
 )
 
 // Saver is an interface for saving the kernel.
@@ -267,17 +268,21 @@ type AsyncMFLoader struct {
 // pagesMetadata and pagesFile. It creates a background goroutine that will
 // load all the MemoryFiles. The background goroutine immediately starts
 // loading the main MemoryFile.
-func NewAsyncMFLoader(pagesMetadata, pagesFile *fd.FD, mainMF *pgalloc.MemoryFile) *AsyncMFLoader {
+// If timeline is provided, it will be used to track async page loading.
+// It takes ownership of the timeline, and will end it when done loading all
+// pages.
+func NewAsyncMFLoader(pagesMetadata, pagesFile *fd.FD, mainMF *pgalloc.MemoryFile, timeline *timing.Timeline) *AsyncMFLoader {
 	mfl := &AsyncMFLoader{
 		privateMFsChan: make(chan map[string]*pgalloc.MemoryFile, 1),
 	}
 	mfl.metadataWg.Add(1)
 	mfl.loadWg.Add(1)
-	go mfl.backgroundGoroutine(pagesMetadata, pagesFile, mainMF)
+	go mfl.backgroundGoroutine(pagesMetadata, pagesFile, mainMF, timeline)
 	return mfl
 }
 
-func (mfl *AsyncMFLoader) backgroundGoroutine(pagesMetadataFD, pagesFileFD *fd.FD, mainMF *pgalloc.MemoryFile) {
+func (mfl *AsyncMFLoader) backgroundGoroutine(pagesMetadataFD, pagesFileFD *fd.FD, mainMF *pgalloc.MemoryFile, timeline *timing.Timeline) {
+	defer timeline.End()
 	defer pagesMetadataFD.Close()
 	defer pagesFileFD.Close()
 	cu := cleanup.Make(func() {
@@ -307,17 +312,20 @@ func (mfl *AsyncMFLoader) backgroundGoroutine(pagesMetadataFD, pagesFileFD *fd.F
 				mfl.loadErrsMu.Unlock()
 			}
 		},
+		Timeline: timeline,
 	}
 
+	timeline.Reached("loading mainMF")
 	log.Infof("Loading metadata for main MemoryFile: %p", mainMF)
 	ctx := context.Background()
 	if err := mainMF.LoadFrom(ctx, pagesMetadata, &opts); err != nil {
 		log.Warningf("Failed to load main MemoryFile %p: %v", mainMF, err)
 		mfl.metadataErr = err
 		return
 	}
-
+	timeline.Reached("waiting for privateMF info")
 	privateMFs := <-mfl.privateMFsChan
+	timeline.Reached("received privateMFs info")
 	log.Infof("Loading metadata for %d private MemoryFiles", len(privateMFs))
 	if err := loadPrivateMemoryFiles(ctx, pagesMetadata, privateMFs, &opts); err != nil {
 		log.Warningf("Failed to load private MemoryFiles: %v", err)
@@ -326,12 +334,14 @@ func (mfl *AsyncMFLoader) backgroundGoroutine(pagesMetadataFD, pagesFileFD *fd.F
 	}
 
 	// Report metadata load completion.
+	timeline.Reached("metadata load done")
 	log.Infof("All MemoryFile metadata has been loaded")
 	cu.Release()()
 
 	// Wait for page loads to complete and report errors.
 	mfl.loadWg.Wait()
 	if loadErr := errors.Join(mfl.loadErrs...); loadErr != nil {
+		timeline.Invalidate("page load failed")
 		log.Warningf("Failed to load MemoryFile pages: %v", loadErr)
 		return
 	}

pkg/sentry/pgalloc/BUILD

@@ -166,6 +166,7 @@ go_library(
         "//pkg/sync",
         "//pkg/sync/locking",
         "//pkg/syncevent",
+        "//pkg/timing",
         "//pkg/usermem",
         "@org_golang_x_sys//unix:go_default_library",
     ],

pkg/sentry/pgalloc/save_restore.go

@@ -40,6 +40,7 @@ import (
 	"gvisor.dev/gvisor/pkg/state/wire"
 	"gvisor.dev/gvisor/pkg/sync"
 	"gvisor.dev/gvisor/pkg/syncevent"
+	"gvisor.dev/gvisor/pkg/timing"
 )
 
 // SaveOpts provides options to MemoryFile.SaveTo().
@@ -219,7 +220,7 @@ func (f *MemoryFile) SaveTo(ctx context.Context, w io.Writer, pw io.Writer, opts
 		savedBytes += maseg.Range().Length()
 	}
 	durPages := time.Since(timePagesStart)
-	log.Infof("MemoryFile(%p): saved pages in %s (%d bytes, %f bytes/second)", f, durPages, savedBytes, float64(savedBytes)/durPages.Seconds())
+	log.Infof("MemoryFile(%p): saved pages in %s (%d bytes, %.3f MiB/s)", f, durPages, savedBytes, float64(savedBytes)/durPages.Seconds()/(1024.0*1024.0))
 
 	return nil
 }
@@ -257,10 +258,18 @@ type LoadOpts struct {
 	PagesFileOffset      uint64
 	OnAsyncPageLoadStart func(*MemoryFile)
 	OnAsyncPageLoadDone  func(*MemoryFile, error)
+
+	// Optional timeline for the restore process.
+	// If async page loading is enabled, a forked timeline will be created for
+	// that async goroutine, so ownership of this timeline remains in the hands
+	// of the caller of LoadFrom.
+	Timeline *timing.Timeline
 }
 
 // LoadFrom loads MemoryFile state from the given stream.
 func (f *MemoryFile) LoadFrom(ctx context.Context, r io.Reader, opts *LoadOpts) error {
+	mfTimeline := opts.Timeline.Fork(fmt.Sprintf("mf:%p", f)).Lease()
+	defer mfTimeline.End()
 	timeMetadataStart := time.Now()
 
 	// Clear sets since non-empty sets will panic if loaded into.
@@ -300,6 +309,7 @@ func (f *MemoryFile) LoadFrom(ctx context.Context, r io.Reader, opts *LoadOpts)
 		return err
 	}
 	f.chunks.Store(&chunks)
+	mfTimeline.Reached("metadata loaded")
 	log.Infof("MemoryFile(%p): loaded metadata in %s", f, time.Since(timeMetadataStart))
 	if err := f.file.Truncate(int64(len(chunks)) * chunkSize); err != nil {
 		return fmt.Errorf("failed to truncate MemoryFile: %w", err)
@@ -322,6 +332,7 @@ func (f *MemoryFile) LoadFrom(ctx context.Context, r io.Reader, opts *LoadOpts)
 		if errno != 0 {
 			return fmt.Errorf("failed to mmap MemoryFile: %w", errno)
 		}
+		mfTimeline.Reached("mmaped chunks")
 		for i := range chunks {
 			chunk := &chunks[i]
 			chunk.mapping = m
@@ -373,6 +384,7 @@ func (f *MemoryFile) LoadFrom(ctx context.Context, r io.Reader, opts *LoadOpts)
 			qavail:       aplQueueCapacity,
 			fd:           int32(opts.PagesFile.FD()),
 			opsBusy:      bitmap.New(aplQueueCapacity),
+			timeline:     mfTimeline.Transfer(),
 		}
 		apl = &aplg.apl
 		// Mark ops in opsBusy that don't actually exist as permanently busy.
@@ -665,6 +677,9 @@ type aplGoroutine struct {
 
 	// ops stores all aplOps.
 	ops [aplQueueCapacity]aplOp
+
+	// Optional timeline for tracking async page loading.
+	timeline *timing.Timeline
 }
 
 // Possible events in aplGoroutine.lfStatus:
@@ -855,6 +870,9 @@ func (g *aplGoroutine) main() {
 	apl := &g.apl
 	f := g.f
 	q := g.q
+	t := g.timeline
+	defer t.End()
+	t.Reached("aplGoroutine.main")
 	defer func() {
 		// Destroy q first since this synchronously stops inflight I/O.
 		q.Destroy()
@@ -932,7 +950,9 @@ func (g *aplGoroutine) main() {
 					}
 					durDelta := time.Duration(now - timeLast)
 					bytesLoadedDelta := bytesLoaded - bytesLoadedLast
-					log.Infof("MemoryFile(%p): async page loading in progress for %s (%d bytes, %.3f MB/s); since last update %s ago: %d bytes, %.3f MB/s; %d waiters waited %v~%v for %d bytes", f, durTotal.Round(time.Millisecond), bytesLoaded, float64(bytesLoaded)*1e-6/durTotal.Seconds(), durDelta.Round(time.Millisecond), bytesLoadedDelta, float64(bytesLoadedDelta)*1e-6/durDelta.Seconds(), totalWaiters, durWaitedOne.Round(time.Millisecond), durWaitedTotal.Round(time.Millisecond), bytesWaited)
+					bandwidthSinceLast := float64(bytesLoadedDelta) * 1e-6 / durDelta.Seconds()
+					t.Reached(fmt.Sprintf("%.3f MB/s", bandwidthSinceLast))
+					log.Infof("MemoryFile(%p): async page loading in progress for %s (%d bytes, %.3f MB/s); since last update %s ago: %d bytes, %.3f MB/s; %d waiters waited %v~%v for %d bytes", f, durTotal.Round(time.Millisecond), bytesLoaded, float64(bytesLoaded)*1e-6/durTotal.Seconds(), durDelta.Round(time.Millisecond), bytesLoadedDelta, bandwidthSinceLast, totalWaiters, durWaitedOne.Round(time.Millisecond), durWaitedTotal.Round(time.Millisecond), bytesWaited)
 					timeLast = now
 					bytesLoadedLast = bytesLoaded
 				}

pkg/timing/timing.go

@@ -86,6 +86,10 @@ type Timeline struct {
 	// children is a list of forked timelines that are children of this one.
 	// Note that children do not necessarily need to end before the parent does.
 	children []*Timeline
+
+	// invalidReason, if non-empty, is the reason why this Timeline is invalid.
+	// A Timeline is also invalid if any of its children are invalid.
+	invalidReason string
 }
 
 // MidPoint is a named point in time on a Timeline.
@@ -243,6 +247,18 @@ func (s *Timeline) End() {
 	}
 }
 
+// Invalidate marks the Timeline as invalid.
+func (s *Timeline) Invalidate(reason string) {
+	if s == nil {
+		return
+	}
+	if s.invalidReason != "" {
+		log.Warningf("Timer for %s: Timeline %s was already invalid (%v), but tried to invalidate again (%v)", s.timer.root.name, s.fullName, s.invalidReason, reason)
+		return
+	}
+	s.invalidReason = reason
+}
+
 // A Lease is a reference to a Timeline that is valid until the Lease is
 // canceled. After calling Lease on a Timeline, the caller should no longer
 // use the Timeline directly, and should instead use the Lease exclusively.
@@ -342,6 +358,15 @@ func (l *Lease) End() {
 	l.timeline.End()
 }
 
+// Invalidate invalidates the Timeline if the Lease is valid.
+// See `Timeline.Invalidate` for more details.
+func (l *Lease) Invalidate(reason string) {
+	if l == nil || !l.valid {
+		return
+	}
+	l.timeline.Invalidate(reason)
+}
+
 // Transfer invalidates the current Lease and returns the underlying Timeline.
 // Typically useful when transferring ownership of a Timeline to a different
 // goroutine while giving up ownership in the current one.
@@ -608,6 +633,16 @@ func (t *Timer) Log() {
 	t.root.traverse(nil, func(_, child *Timeline) {
 		flatTimelines = append(flatTimelines, child)
 	})
+	var invalidReasons []string
+	for _, timeline := range flatTimelines {
+		if timeline.invalidReason != "" {
+			invalidReasons = append(invalidReasons, timeline.invalidReason)
+		}
+	}
+	if len(invalidReasons) > 0 {
+		log.Warningf("Timer for %s: Timeline was invalidated, so not displaying timing data: %v", t.root.name, invalidReasons)
+		return
+	}
 	var events []event
 	for _, timeline := range flatTimelines {
 		events = append(events, event{when: timeline.start, point: point{timeline: timeline, pointType: pointTypeStart}})

runsc/boot/BUILD

@@ -125,6 +125,7 @@ go_library(
         "//pkg/tcpip/transport/raw",
         "//pkg/tcpip/transport/tcp",
         "//pkg/tcpip/transport/udp",
+        "//pkg/timing",
         "//pkg/urpc",
         "//runsc/boot/filter",
         "//runsc/boot/portforward",
@@ -134,6 +135,7 @@ go_library(
         "//runsc/profile",
         "//runsc/specutils",
         "//runsc/specutils/seccomp",
+        "//runsc/starttime",
         "//runsc/version",
         "@com_github_moby_sys_capability//:go_default_library",
         "@com_github_opencontainers_runtime_spec//specs-go:go_default_library",

runsc/boot/controller.go

@@ -38,10 +38,12 @@ import (
 	"gvisor.dev/gvisor/pkg/sentry/socket/plugin"
 	"gvisor.dev/gvisor/pkg/sentry/state"
 	"gvisor.dev/gvisor/pkg/sentry/vfs"
+	"gvisor.dev/gvisor/pkg/timing"
 	"gvisor.dev/gvisor/pkg/urpc"
 	"gvisor.dev/gvisor/runsc/boot/procfs"
 	"gvisor.dev/gvisor/runsc/config"
 	"gvisor.dev/gvisor/runsc/specutils"
+	"gvisor.dev/gvisor/runsc/starttime"
 	"gvisor.dev/gvisor/runsc/version"
 )
 
@@ -496,9 +498,12 @@ type RestoreOpts struct {
 // created, and the kernel is recreated with the restore state file. The
 // container then sends the signal to start.
 func (cm *containerManager) Restore(o *RestoreOpts, _ *struct{}) error {
+	timer := starttime.Timer("Restore")
+	timer.Reached("cm.Restore RPC")
 	log.Debugf("containerManager.Restore")
 
 	cm.l.mu.Lock()
+	timer.Reached("cm.l.mu.Lock")
 	cu := cleanup.Make(cm.l.mu.Unlock)
 	defer cu.Clean()
 
@@ -538,10 +543,12 @@ func (cm *containerManager) Restore(o *RestoreOpts, _ *struct{}) error {
 		onRestoreDone: cm.onRestoreDone,
 		stateFile:     reader,
 		background:    o.Background,
+		timer:         timer,
 		mainMF:        mf,
 	}
 	cm.l.restoreDone = sync.NewCond(&cm.l.mu)
 	cm.l.state = restoringUnstarted
+
 	// Release `cm.l.mu`.
 	cu.Clean()
 
@@ -560,7 +567,7 @@ func (cm *containerManager) Restore(o *RestoreOpts, _ *struct{}) error {
 		fileIdx++
 
 		// This immediately starts loading the main MemoryFile asynchronously.
-		cm.restorer.asyncMFLoader = kernel.NewAsyncMFLoader(pagesMetadata, pagesFile, cm.restorer.mainMF)
+		cm.restorer.asyncMFLoader = kernel.NewAsyncMFLoader(pagesMetadata, pagesFile, cm.restorer.mainMF, timer.Fork("PagesFileLoader"))
 	}
 
 	if o.HaveDeviceFile {
@@ -574,9 +581,11 @@ func (cm *containerManager) Restore(o *RestoreOpts, _ *struct{}) error {
 	if fileIdx < len(o.Files) {
 		return fmt.Errorf("more files passed to Restore than expected")
 	}
+	timer.Reached("restorer ok")
 
 	// Pause the kernel while we build a new one.
 	cm.l.k.Pause()
+	timer.Reached("kernel paused")
 
 	var count int
 	countStr, ok := metadata[ContainerCountKey]
@@ -614,7 +623,7 @@ func (cm *containerManager) Restore(o *RestoreOpts, _ *struct{}) error {
 	if checkpointVersion != currentVersion {
 		return fmt.Errorf("runsc version does not match across checkpoint restore, checkpoint: %v current: %v", checkpointVersion, currentVersion)
 	}
-	return cm.restorer.restoreContainerInfo(cm.l, &cm.l.root)
+	return cm.restorer.restoreContainerInfo(cm.l, &cm.l.root, timer.Fork("cont:root"))
 }
 
 func (cm *containerManager) onRestoreDone() {
@@ -626,9 +635,11 @@ func (cm *containerManager) onRestoreDone() {
 }
 
 func (cm *containerManager) RestoreSubcontainer(args *StartArgs, _ *struct{}) error {
+	timeline := timing.OrphanTimeline(fmt.Sprintf("cont:%s", args.CID[0:min(8, len(args.CID))]), gtime.Now()).Lease()
+	defer timeline.End()
 	log.Debugf("containerManager.RestoreSubcontainer, cid: %s, args: %+v", args.CID, args)
-
 	cm.l.mu.Lock()
+	timeline.Reached("cm.l.mu.Lock")
 	state := cm.l.state
 	cm.l.mu.Unlock()
 	if state != restoringUnstarted {
@@ -656,6 +667,7 @@ func (cm *containerManager) RestoreSubcontainer(args *StartArgs, _ *struct{}) er
 
 	// All validation passed, logs the spec for debugging.
 	specutils.LogSpecDebug(args.Spec, args.Conf.OCISeccomp)
+	timeline.Reached("spec validated")
 
 	goferFiles := args.Files
 	var stdios []*fd.FD
@@ -695,7 +707,8 @@ func (cm *containerManager) RestoreSubcontainer(args *StartArgs, _ *struct{}) er
 		return fmt.Errorf("error dup'ing gofer files: %w", err)
 	}
 
-	if err := cm.restorer.restoreSubcontainer(args.Spec, args.Conf, cm.l, args.CID, stdios, goferFDs, goferFilestoreFDs, devGoferFD, args.GoferMountConfs); err != nil {
+	err = cm.restorer.restoreSubcontainer(args.Spec, args.Conf, cm.l, args.CID, stdios, goferFDs, goferFilestoreFDs, devGoferFD, args.GoferMountConfs, timeline.Transfer())
+	if err != nil {
 		log.Debugf("containerManager.RestoreSubcontainer failed, cid: %s, args: %+v, err: %v", args.CID, args, err)
 		return err
 	}
@@ -712,7 +725,7 @@ func (cm *containerManager) Pause(_, _ *struct{}) error {
 // Resume resumes all tasks.
 func (cm *containerManager) Resume(_, _ *struct{}) error {
 	cm.l.k.Unpause()
-	return postResumeImpl(cm.l)
+	return postResumeImpl(cm.l, nil)
 }
 
 // Wait waits for the init process in the given container.