Include TimeSaved metric in Run Summaries

cli/integration_tests/cache_state.t

@@ -29,5 +29,8 @@ Validate that local cache is true in dry run
   $ cat dry.json | jq '.tasks | map(select(.taskId == "my-app#build")) | .[0].cache'
   {
     "local": true,
-    "remote": false
+    "remote": false,
+    "status": "HIT",
+    "source": "LOCAL",
+    "timeSaved": [0-9]+ (re)
   }

cli/integration_tests/dry_json/monorepo.t

@@ -93,7 +93,9 @@ Setup
     "hashOfExternalDependencies": "ccab0b28617f1f56",
     "cache": {
       "local": false,
-      "remote": false
+      "remote": false,
+      "status": "MISS",
+      "timeSaved": 0
     },
     "command": "echo 'building'",
     "cliArguments": [],
@@ -143,7 +145,9 @@ Setup
     "hashOfExternalDependencies": "ccab0b28617f1f56",
     "cache": {
       "local": false,
-      "remote": false
+      "remote": false,
+      "status": "MISS",
+      "timeSaved": 0
     },
     "command": "echo 'building'",
     "cliArguments": [],

cli/integration_tests/dry_json/single_package.t

@@ -44,7 +44,9 @@ Setup
         "hashOfExternalDependencies": "",
         "cache": {
           "local": false,
-          "remote": false
+          "remote": false,
+          "status": "MISS",
+          "timeSaved": 0
         },
         "command": "echo 'building' \u003e foo",
         "cliArguments": [],

cli/integration_tests/dry_json/single_package_no_config.t

@@ -39,7 +39,9 @@ Setup
         "hashOfExternalDependencies": "",
         "cache": {
           "local": false,
-          "remote": false
+          "remote": false,
+          "status": "MISS",
+          "timeSaved": 0
         },
         "command": "echo 'building'",
         "cliArguments": [],

cli/integration_tests/dry_json/single_package_with_deps.t

@@ -53,7 +53,9 @@ Setup
         "hashOfExternalDependencies": "",
         "cache": {
           "local": false,
-          "remote": false
+          "remote": false,
+          "status": "MISS",
+          "timeSaved": 0
         },
         "command": "echo 'building' \u003e foo",
         "cliArguments": [],
@@ -100,7 +102,9 @@ Setup
         "hashOfExternalDependencies": "",
         "cache": {
           "local": false,
-          "remote": false
+          "remote": false,
+          "status": "MISS",
+          "timeSaved": 0
         },
         "command": "[[ ( -f foo ) \u0026\u0026 $(cat foo) == 'building' ]]",
         "cliArguments": [],

cli/integration_tests/run_summary/error.t

@@ -40,7 +40,9 @@ Validate that we got a full task summary for the failed task with an error in .e
     "hashOfExternalDependencies": "ccab0b28617f1f56",
     "cache": {
       "local": false,
-      "remote": false
+      "remote": false,
+      "status": "MISS",
+      "timeSaved": 0
     },
     "command": "exit 4",
     "cliArguments": [],

cli/integration_tests/run_summary/monorepo.t

@@ -75,12 +75,17 @@ Setup
   $ echo $FIRST_APP_BUILD | jq '.cache'
   {
     "local": false,
-    "remote": false
+    "remote": false,
+    "status": "MISS",
+    "timeSaved": 0
   }
   $ echo $SECOND_APP_BUILD | jq '.cache'
   {
     "local": true,
-    "remote": false
+    "remote": false,
+    "status": "HIT",
+    "source": "LOCAL",
+    "timeSaved": [0-9]+ (re)
   }
 
 # Some validation of util#build

cli/integration_tests/run_summary/single-package.t

@@ -82,5 +82,7 @@ Check
   $ echo $TASK_SUMMARY | jq '.cache'
   {
     "local": false,
-    "remote": false
+    "remote": false,
+    "status": "MISS",
+    "timeSaved": 0
   }

cli/internal/cache/cache.go

@@ -36,8 +36,16 @@ type ItemStatus struct {
 	Remote bool `json:"remote"`
 }
 
-const cacheEventHit = "HIT"
-const cacheEventMiss = "MISS"
+const (
+	// CacheSourceFS is a constant to indicate local cache hit
+	CacheSourceFS = "LOCAL"
+	// CacheSourceRemote is a constant to indicate remote cache hit
+	CacheSourceRemote = "REMOTE"
+	// CacheEventHit is a constant to indicate a cache hit
+	CacheEventHit = "HIT"
+	// CacheEventMiss is a constant to indicate a cache miss
+	CacheEventMiss = "MISS"
+)
 
 type CacheEvent struct {
 	Source   string `mapstructure:"source"`

cli/internal/cache/cache_fs.go

@@ -88,12 +88,12 @@ func (f *fsCache) Exists(hash string) ItemStatus {
 func (f *fsCache) logFetch(hit bool, hash string, duration int) {
 	var event string
 	if hit {
-		event = cacheEventHit
+		event = CacheEventHit
 	} else {
-		event = cacheEventMiss
+		event = CacheEventMiss
 	}
 	payload := &CacheEvent{
-		Source:   "LOCAL",
+		Source:   CacheSourceFS,
 		Event:    event,
 		Hash:     hash,
 		Duration: duration,

cli/internal/cache/cache_http.go

@@ -168,12 +168,12 @@ func (cache *httpCache) Exists(key string) ItemStatus {
 func (cache *httpCache) logFetch(hit bool, hash string, duration int) {
 	var event string
 	if hit {
-		event = cacheEventHit
+		event = CacheEventHit
 	} else {
-		event = cacheEventMiss
+		event = CacheEventMiss
 	}
 	payload := &CacheEvent{
-		Source:   "REMOTE",
+		Source:   CacheSourceRemote,
 		Event:    event,
 		Hash:     hash,
 		Duration: duration,

cli/internal/run/dry_run.go

@@ -105,7 +105,7 @@ func populateCacheState(turboCache cache.Cache, taskSummaries []*runsummary.Task
 			for index := range queue {
 				task := taskSummaries[index]
 				itemStatus := turboCache.Exists(task.Hash)
-				task.CacheState = itemStatus
+				task.CacheSummary = runsummary.NewTaskCacheSummary(itemStatus, nil)
 			}
 		}()
 	}

cli/internal/run/real_run.go

@@ -105,7 +105,7 @@ func RealRun(
 		if taskExecutionSummary != nil {
 			taskSummary.ExpandedOutputs = taskHashTracker.GetExpandedOutputs(taskSummary.TaskID)
 			taskSummary.Execution = taskExecutionSummary
-			taskSummary.CacheState = taskHashTracker.GetCacheStatus(taskSummary.TaskID)
+			taskSummary.CacheSummary = taskHashTracker.GetCacheStatus(taskSummary.TaskID)
 
 			// lock since multiple things to be appending to this array at the same time
 			mu.Lock()
@@ -271,13 +271,20 @@ func (ec *execContext) exec(ctx gocontext.Context, packageTask *nodes.PackageTas
 		ErrorPrefix:  prettyPrefix,
 		WarnPrefix:   prettyPrefix,
 	}
-	cacheStatus, err := taskCache.RestoreOutputs(ctx, prefixedUI, progressLogger)
-	ec.taskHashTracker.SetCacheStatus(packageTask.TaskID, cacheStatus)
 
-	hit := cacheStatus.Local || cacheStatus.Remote
+	cacheStatus, timeSaved, err := taskCache.RestoreOutputs(ctx, prefixedUI, progressLogger)
+
+	// It's safe to set the CacheStatus even if there's an error, because if there's
+	// an error, the 0 values are actually what we want. We save cacheStatus and timeSaved
+	// for the task, so that even if there's an error, we have those values for the taskSummary.
+	ec.taskHashTracker.SetCacheStatus(
+		packageTask.TaskID,
+		runsummary.NewTaskCacheSummary(cacheStatus, &timeSaved),
+	)
+
 	if err != nil {
 		prefixedUI.Error(fmt.Sprintf("error fetching from cache: %s", err))
-	} else if hit {
+	} else if cacheStatus.Local || cacheStatus.Remote { // If there was a cache hit
 		ec.taskHashTracker.SetExpandedOutputs(packageTask.TaskID, taskCache.ExpandedOutputs)
 		// We only cache successful executions, so we can assume this is a successCode exit.
 		tracer(runsummary.TargetCached, nil, &successCode)

cli/internal/runcache/runcache.go

@@ -108,13 +108,14 @@ type TaskCache struct {
 }
 
 // RestoreOutputs attempts to restore output for the corresponding task from the cache.
-// Returns true if successful.
-func (tc *TaskCache) RestoreOutputs(ctx context.Context, prefixedUI *cli.PrefixedUi, progressLogger hclog.Logger) (cache.ItemStatus, error) {
+// Returns the cacheStatus, the timeSaved, and error values, so the consumer can understand
+// what happened in here.
+func (tc *TaskCache) RestoreOutputs(ctx context.Context, prefixedUI *cli.PrefixedUi, progressLogger hclog.Logger) (cache.ItemStatus, int, error) {
 	if tc.cachingDisabled || tc.rc.readsDisabled {
 		if tc.taskOutputMode != util.NoTaskOutput && tc.taskOutputMode != util.ErrorTaskOutput {
 			prefixedUI.Output(fmt.Sprintf("cache bypass, force executing %s", ui.Dim(tc.hash)))
 		}
-		return cache.ItemStatus{Local: false, Remote: false}, nil
+		return cache.ItemStatus{Local: false, Remote: false}, 0, nil
 	}
 
 	changedOutputGlobs, err := tc.rc.outputWatcher.GetChangedOutputs(ctx, tc.hash, tc.repoRelativeGlobs.Inclusions)
@@ -126,25 +127,26 @@ func (tc *TaskCache) RestoreOutputs(ctx context.Context, prefixedUI *cli.Prefixe
 
 	hasChangedOutputs := len(changedOutputGlobs) > 0
 	var cacheStatus cache.ItemStatus
-
+	var timeSaved int
 	if hasChangedOutputs {
 		// Note that we currently don't use the output globs when restoring, but we could in the
 		// future to avoid doing unnecessary file I/O. We also need to pass along the exclusion
 		// globs as well.
-		itemStatus, restoredFiles, _, err := tc.rc.cache.Fetch(tc.rc.repoRoot, tc.hash, nil)
+		itemStatus, restoredFiles, duration, err := tc.rc.cache.Fetch(tc.rc.repoRoot, tc.hash, nil)
 		hit := itemStatus.Local || itemStatus.Remote
+		timeSaved = duration
 		tc.ExpandedOutputs = restoredFiles
 		// Assign to this variable outside this closure so we can return at the end of the function
 		cacheStatus = itemStatus
 		if err != nil {
 			// If there was an error fetching from cache, we'll say there was no cache hit
-			return cache.ItemStatus{Local: false, Remote: false}, err
+			return cache.ItemStatus{Local: false, Remote: false}, 0, err
 		} else if !hit {
 			if tc.taskOutputMode != util.NoTaskOutput && tc.taskOutputMode != util.ErrorTaskOutput {
 				prefixedUI.Output(fmt.Sprintf("cache miss, executing %s", ui.Dim(tc.hash)))
 			}
 			// If there was no hit, we can also say there was no hit
-			return cache.ItemStatus{Local: false, Remote: false}, nil
+			return cache.ItemStatus{Local: false, Remote: false}, 0, nil
 		}
 
 		if err := tc.rc.outputWatcher.NotifyOutputsWritten(ctx, tc.hash, tc.repoRelativeGlobs); err != nil {
@@ -172,7 +174,9 @@ func (tc *TaskCache) RestoreOutputs(ctx context.Context, prefixedUI *cli.Prefixe
 	default:
 		// NoLogs, do not output anything
 	}
-	return cacheStatus, nil
+	// TODO: timeSaved could be part of cacheStatus, so we don't have to make a new struct
+	// downstream, but this would be a more invasive change right now.
+	return cacheStatus, timeSaved, nil
 }
 
 // ReplayLogFile writes out the stored logfile to the terminal

cli/internal/runsummary/format_text.go

@@ -67,8 +67,8 @@ func (rsm Meta) FormatAndPrintText(workspaceInfos workspace.Catalog) error {
 			fmt.Fprintln(w, util.Sprintf("  ${GREY}Package\t=\t%s\t${RESET}", task.Package))
 		}
 		fmt.Fprintln(w, util.Sprintf("  ${GREY}Hash\t=\t%s\t${RESET}", task.Hash))
-		fmt.Fprintln(w, util.Sprintf("  ${GREY}Cached (Local)\t=\t%s\t${RESET}", strconv.FormatBool(task.CacheState.Local)))
-		fmt.Fprintln(w, util.Sprintf("  ${GREY}Cached (Remote)\t=\t%s\t${RESET}", strconv.FormatBool(task.CacheState.Remote)))
+		fmt.Fprintln(w, util.Sprintf("  ${GREY}Cached (Local)\t=\t%s\t${RESET}", strconv.FormatBool(task.CacheSummary.Local)))
+		fmt.Fprintln(w, util.Sprintf("  ${GREY}Cached (Remote)\t=\t%s\t${RESET}", strconv.FormatBool(task.CacheSummary.Remote)))
 
 		if !rsm.singlePackage {
 			fmt.Fprintln(w, util.Sprintf("  ${GREY}Directory\t=\t%s\t${RESET}", task.Dir))

cli/internal/runsummary/spaces.go

@@ -40,9 +40,15 @@ type spacesRunPayload struct {
 	// gitSha          string
 }
 
+// spacesCacheStatus is the same as TaskCacheSummary so we can convert
+// spacesCacheStatus(cacheSummary), but change the json tags, to omit local and remote fields
 type spacesCacheStatus struct {
-	Status string `json:"status,omitempty"`
-	Source string `json:"source,omitempty"`
+	// omitted fields, but here so we can convert from TaskCacheSummary easily
+	Local     bool   `json:"-"`
+	Remote    bool   `json:"-"`
+	Status    string `json:"status"` // should always be there
+	Source    string `json:"source,omitempty"`
+	TimeSaved int    `json:"timeSaved"`
 }
 
 type spacesTask struct {
@@ -84,32 +90,17 @@ func newSpacesDonePayload(runsummary *RunSummary) *spacesRunPayload {
 }
 
 func newSpacesTaskPayload(taskSummary *TaskSummary) *spacesTask {
-	// Set the cache source. Local and Remote shouldn't _both_ be true.
-	var source string
-	if taskSummary.CacheState.Local {
-		source = "LOCAL"
-	} else if taskSummary.CacheState.Remote {
-		source = "REMOTE"
-	}
-	status := "MISS"
-	if source != "" {
-		status = "HIT"
-	}
-
 	startTime := taskSummary.Execution.startAt.UnixMilli()
 	endTime := taskSummary.Execution.endTime().UnixMilli()
 
 	return &spacesTask{
-		Key:       taskSummary.TaskID,
-		Name:      taskSummary.Task,
-		Workspace: taskSummary.Package,
-		Hash:      taskSummary.Hash,
-		StartTime: startTime,
-		EndTime:   endTime,
-		Cache: spacesCacheStatus{
-			Status: status,
-			Source: source,
-		},
+		Key:          taskSummary.TaskID,
+		Name:         taskSummary.Task,
+		Workspace:    taskSummary.Package,
+		Hash:         taskSummary.Hash,
+		StartTime:    startTime,
+		EndTime:      endTime,
+		Cache:        spacesCacheStatus(taskSummary.CacheSummary), // wrapped so we can remove fields
 		ExitCode:     *taskSummary.Execution.exitCode,
 		Dependencies: taskSummary.Dependencies,
 		Dependents:   taskSummary.Dependents,

cli/internal/runsummary/task_summary.go

@@ -7,6 +7,47 @@ import (
 	"github.com/vercel/turbo/cli/internal/util"
 )
 
+// TaskCacheSummary is an extended version of cache.ItemStatus
+// that includes TimeSaved and some better data.
+type TaskCacheSummary struct {
+	Local     bool   `json:"local"`            // Deprecated, but keeping around for --dry=json
+	Remote    bool   `json:"remote"`           // Deprecated, but keeping around for --dry=json
+	Status    string `json:"status"`           // should always be there
+	Source    string `json:"source,omitempty"` // can be empty on status:miss
+	TimeSaved int    `json:"timeSaved"`        // always include, but can be 0
+}
+
+// NewTaskCacheSummary decorates a cache.ItemStatus into a TaskCacheSummary
+// Importantly, it adds the derived keys of `source` and `status` based on
+// the local/remote booleans. It would be nice if these were just included
+// from upstream, but that is a more invasive change.
+func NewTaskCacheSummary(itemStatus cache.ItemStatus, timeSaved *int) TaskCacheSummary {
+	status := cache.CacheEventMiss
+	if itemStatus.Local || itemStatus.Remote {
+		status = cache.CacheEventHit
+	}
+
+	var source string
+	if itemStatus.Local {
+		source = cache.CacheSourceFS
+	} else if itemStatus.Remote {
+		source = cache.CacheSourceRemote
+	}
+
+	cs := TaskCacheSummary{
+		// copy these over
+		Local:  itemStatus.Local,
+		Remote: itemStatus.Remote,
+		Status: status,
+		Source: source,
+	}
+	// add in a dereferences timeSaved, should be 0 if nil
+	if timeSaved != nil {
+		cs.TimeSaved = *timeSaved
+	}
+	return cs
+}
+
 // TaskSummary contains information about the task that was about to run
 // TODO(mehulkar): `Outputs` and `ExcludedOutputs` are slightly redundant
 // as the information is also available in ResolvedTaskDefinition. We could remove them
@@ -18,7 +59,7 @@ type TaskSummary struct {
 	Hash                   string                                `json:"hash"`
 	ExpandedInputs         map[turbopath.AnchoredUnixPath]string `json:"inputs"`
 	ExternalDepsHash       string                                `json:"hashOfExternalDependencies"`
-	CacheState             cache.ItemStatus                      `json:"cache"`
+	CacheSummary           TaskCacheSummary                      `json:"cache"`
 	Command                string                                `json:"command"`
 	CommandArguments       []string                              `json:"cliArguments"`
 	Outputs                []string                              `json:"outputs"`