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

PiperOrigin-RevId: 758919824

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,8 +312,10 @@ 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 {
@@ -316,8 +323,9 @@ func (mfl *AsyncMFLoader) backgroundGoroutine(pagesMetadataFD, pagesFileFD *fd.F
 		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.

runsc/boot/restore.go

@@ -40,6 +40,7 @@ import (
 	"gvisor.dev/gvisor/pkg/sentry/watchdog"
 	"gvisor.dev/gvisor/pkg/sync"
 	"gvisor.dev/gvisor/pkg/tcpip/stack"
+	"gvisor.dev/gvisor/pkg/timing"
 	"gvisor.dev/gvisor/runsc/boot/pprof"
 	"gvisor.dev/gvisor/runsc/config"
 	"gvisor.dev/gvisor/runsc/specutils"
@@ -83,6 +84,10 @@ type restorer struct {
 	// stateFile is a reader for the statefile.
 	stateFile io.ReadCloser
 
+	// timer is the timer for the restore process.
+	// The `restorer` owns the timer and will end it when restore is complete.
+	timer *timing.Timer
+
 	// If background is true, pagesFile may continue to be read after
 	// restorer.restore() returns.
 	background bool
@@ -111,7 +116,10 @@ type restorer struct {
 	checkpointedSpecs map[string]*specs.Spec
 }
 
-func (r *restorer) restoreSubcontainer(spec *specs.Spec, conf *config.Config, l *Loader, cid string, stdioFDs, goferFDs, goferFilestoreFDs []*fd.FD, devGoferFD *fd.FD, goferMountConfs []GoferMountConf) error {
+// restoreSubcontainer restores a subcontainer.
+// `subcontainerTimeline` must either be nil or an orphaned timeline.
+// It takes ownership of subcontainerTimeline and will end it.
+func (r *restorer) restoreSubcontainer(spec *specs.Spec, conf *config.Config, l *Loader, cid string, stdioFDs, goferFDs, goferFilestoreFDs []*fd.FD, devGoferFD *fd.FD, goferMountConfs []GoferMountConf, subcontainerTimeline *timing.Timeline) error {
 	containerName := l.registerContainer(spec, cid)
 	info := &containerInfo{
 		cid:               cid,
@@ -124,12 +132,18 @@ func (r *restorer) restoreSubcontainer(spec *specs.Spec, conf *config.Config, l
 		goferFilestoreFDs: goferFilestoreFDs,
 		goferMountConfs:   goferMountConfs,
 	}
-	return r.restoreContainerInfo(l, info)
+	r.timer.Adopt(subcontainerTimeline)
+	return r.restoreContainerInfo(l, info, subcontainerTimeline)
 }
 
-func (r *restorer) restoreContainerInfo(l *Loader, info *containerInfo) error {
+// restoreContainerInfo restores a container.
+// It takes ownership of containerTimeline and will end it.
+func (r *restorer) restoreContainerInfo(l *Loader, info *containerInfo, containerTimeline *timing.Timeline) error {
 	r.mu.Lock()
 	defer r.mu.Unlock()
+	containerTiming := containerTimeline.Lease()
+	defer containerTiming.End()
+	containerTiming.Reached("restorer locked")
 
 	for _, container := range r.containers {
 		if container.containerName == info.containerName {
@@ -142,12 +156,15 @@ func (r *restorer) restoreContainerInfo(l *Loader, info *containerInfo) error {
 
 	r.containers = append(r.containers, info)
 
-	log.Infof("Restored container %d of %d", len(r.containers), r.totalContainers)
 	if log.IsLogging(log.Debug) {
 		for i, fd := range info.stdioFDs {
 			log.Debugf("Restore app FD: %d host FD: %d", i, fd.FD())
 		}
 	}
+	containerTiming.End()
+	log.Infof("Restored container %d of %d", len(r.containers), r.totalContainers)
+
+	// Non-container-specific restore work:
 
 	if len(r.containers) == r.totalContainers {
 		if err := specutils.RestoreValidateSpec(r.checkpointedSpecs, l.GetContainerSpecs(), l.root.conf); err != nil {
@@ -175,6 +192,7 @@ func (r *restorer) restore(l *Loader) error {
 	// Create a new root network namespace with the network stack of the
 	// old kernel to preserve the existing network configuration.
 	oldStack, oldInetStack := createNetworkStackForRestore(l)
+	r.timer.Reached("netstack created")
 
 	// Reset the network stack in the network namespace to nil before
 	// replacing the kernel. This will not free the network stack when this
@@ -254,19 +272,23 @@ func (r *restorer) restore(l *Loader) error {
 	}
 
 	// Load the state.
+	r.timer.Reached("loading kernel")
 	if err := l.k.LoadFrom(ctx, r.stateFile, r.asyncMFLoader == nil, nil, oldInetStack, time.NewCalibratedClocks(), &vfs.CompleteRestoreOptions{}, l.saveRestoreNet); err != nil {
 		return fmt.Errorf("failed to load kernel: %w", err)
 	}
+	r.timer.Reached("kernel loaded")
 
 	if r.asyncMFLoader != nil {
 		if r.background {
 			if err := r.asyncMFLoader.WaitMetadata(); err != nil {
 				return err
 			}
+			r.timer.Reached("MF metadata loaded")
 		} else {
 			if err := r.asyncMFLoader.Wait(); err != nil {
 				return err
 			}
+			r.timer.Reached("MFs loaded")
 		}
 	}
 
@@ -329,18 +351,23 @@ func (r *restorer) restore(l *Loader) error {
 	// Release `l.mu` before calling into callbacks.
 	cu.Clean()
 
+	r.timer.Reached("Starting sandbox")
 	if err := r.readyToStart(); err != nil {
 		return fmt.Errorf("restorer.readyToStart callback failed: %w", err)
 	}
 
 	r.stateFile.Close()
 
+	postRestoreThread := r.timer.Fork("postRestore")
 	go func() {
-		if err := postRestoreImpl(l); err != nil {
+		defer postRestoreThread.End()
+		postRestoreThread.Reached("scheduled")
+		if err := postRestoreImpl(l, postRestoreThread); err != nil {
 			log.Warningf("Killing the sandbox after post restore work failed: %v", err)
 			l.k.Kill(linux.WaitStatusTerminationSignal(linux.SIGKILL))
 			return
 		}
+		postRestoreThread.Reached("post restore done")
 
 		// Now that post restore work succeeded, increment the checkpoint gen
 		// manually. The count was saved while the previous kernel was being saved
@@ -359,9 +386,19 @@ func (r *restorer) restore(l *Loader) error {
 		}
 
 		r.onRestoreDone()
+		postRestoreThread.Reached("kernel notified")
 
 		log.Infof("Restore successful")
 	}()
+
+	// Transfer ownership of the `timer` to a new goroutine.
+	// This is because `timer.Log` blocks until all timed tasks are finished,
+	// but some restore tasks may still run in the background, and we don't
+	// want to block this function until they finish.
+	timer := r.timer
+	r.timer = nil
+	go timer.Log()
+
 	return nil
 }
 
@@ -404,7 +441,7 @@ func (l *Loader) save(o *control.SaveOpts) (err error) {
 	}
 
 	if o.Resume {
-		if err := postResumeImpl(l); err != nil {
+		if err := postResumeImpl(l, nil); err != nil {
 			return err
 		}
 	}

runsc/boot/restore_impl.go

@@ -21,6 +21,7 @@ import (
 	specs "github.com/opencontainers/runtime-spec/specs-go"
 	"gvisor.dev/gvisor/pkg/sentry/control"
 	"gvisor.dev/gvisor/pkg/sentry/fsimpl/proc"
+	"gvisor.dev/gvisor/pkg/timing"
 	"gvisor.dev/gvisor/runsc/config"
 )
 
@@ -29,12 +30,12 @@ func preSaveImpl(*Loader, *control.SaveOpts) error {
 }
 
 // Precondition: The kernel should be running.
-func postRestoreImpl(*Loader) error {
+func postRestoreImpl(*Loader, *timing.Timeline) error {
 	return nil
 }
 
 // Precondition: The kernel should be running.
-func postResumeImpl(*Loader) error {
+func postResumeImpl(*Loader, *timing.Timeline) error {
 	return nil
 }
 

runsc/cmd/restore.go

@@ -153,7 +153,8 @@ func (r *Restore) Execute(_ context.Context, f *flag.FlagSet, args ...any) subco
 	}
 
 	log.Debugf("Restore: %v", r.imagePath)
-	if err := c.Restore(conf, r.imagePath, r.direct, r.background); err != nil {
+	err = c.Restore(conf, r.imagePath, r.direct, r.background)
+	if err != nil {
 		return util.Errorf("starting container: %v", err)
 	}
 

runsc/sandbox/sandbox.go

@@ -535,7 +535,6 @@ func (s *Sandbox) Restore(conf *config.Config, spec *specs.Spec, cid string, ima
 
 	} else if !os.IsNotExist(err) {
 		return fmt.Errorf("opening restore pages file %q failed: %v", pagesFileName, err)
-
 	} else {
 		log.Infof("Using single checkpoint file for sandbox %q", s.ID)
 	}