add an option to show JSON cache metrics

cmd/buildctl/build.go

@@ -8,6 +8,7 @@ import (
 	"io"
 	"os"
 	"strings"
+	"time"
 
 	"github.com/containerd/continuity"
 	"github.com/docker/cli/cli/config"
@@ -109,6 +110,10 @@ var buildCommand = cli.Command{
 			Name:  "registry-auth-tlscontext",
 			Usage: "Overwrite TLS configuration when authenticating with registries, e.g. --registry-auth-tlscontext host=https://myserver:2376,insecure=false,ca=/path/to/my/ca.crt,cert=/path/to/my/cert.crt,key=/path/to/my/key.crt",
 		},
+		cli.StringFlag{
+			Name:  "debug-json-cache-metrics",
+			Usage: "Where to output json cache metrics, use 'stdout' or 'stderr' for standard (error) output.",
+		},
 	},
 }
 
@@ -143,7 +148,21 @@ func openTraceFile(clicontext *cli.Context) (*os.File, error) {
 	return nil, nil
 }
 
+func openCacheMetricsFile(clicontext *cli.Context) (*os.File, error) {
+	switch out := clicontext.String("debug-json-cache-metrics"); out {
+	case "stdout":
+		return os.Stdout, nil
+	case "stderr":
+		return os.Stderr, nil
+	case "":
+		return nil, nil
+	default:
+		return os.OpenFile(out, os.O_TRUNC|os.O_CREATE|os.O_WRONLY, 0600)
+	}
+}
+
 func buildAction(clicontext *cli.Context) error {
+	startTime := time.Now()
 	c, err := bccommon.ResolveClient(clicontext)
 	if err != nil {
 		return err
@@ -153,6 +172,11 @@ func buildAction(clicontext *cli.Context) error {
 	if err != nil {
 		return err
 	}
+	cacheMetricsFile, err := openCacheMetricsFile(clicontext)
+	if err != nil {
+		return err
+	}
+
 	var traceEnc *json.Encoder
 	if traceFile != nil {
 		defer traceFile.Close()
@@ -296,6 +320,23 @@ func buildAction(clicontext *cli.Context) error {
 			return nil
 		})
 	}
+	meg, ctx := errgroup.WithContext(bccommon.CommandContext(clicontext))
+	if cacheMetricsFile != nil {
+		bklog.L.Infof("writing JSON cache metrics to %s", cacheMetricsFile.Name())
+		metricsCh := make(chan *client.SolveStatus)
+		pw = progresswriter.Tee(pw, metricsCh)
+		meg.Go(func() error {
+			vtxMap := tailVTXInfo(ctx, pw, metricsCh)
+			if cacheMetricsFile == os.Stdout || cacheMetricsFile == os.Stdin {
+				// make sure everything was printed out to get it as the last line.
+				eg.Wait()
+			} else {
+				defer cacheMetricsFile.Close()
+			}
+			outputCacheMetrics(cacheMetricsFile, startTime, vtxMap)
+			return nil
+		})
+	}
 	mw := progresswriter.NewMultiWriter(pw)
 
 	var writers []progresswriter.Writer
@@ -378,6 +419,9 @@ func buildAction(clicontext *cli.Context) error {
 			}
 		}
 	}
+
+	meg.Wait()
+
 	return nil
 }
 

cmd/buildctl/cachemetrics.go

@@ -0,0 +1,92 @@
+package main
+
+import (
+	"context"
+	"encoding/json"
+	"fmt"
+	"os"
+	"regexp"
+	"strings"
+	"time"
+
+	"github.com/moby/buildkit/client"
+	"github.com/moby/buildkit/util/progress/progresswriter"
+	digest "github.com/opencontainers/go-digest"
+)
+
+type vtxInfo struct {
+	cached    bool
+	completed bool
+	from      bool
+	name      string
+}
+
+func tailVTXInfo(ctx context.Context, pw progresswriter.Writer, metricsCh <-chan *client.SolveStatus) map[digest.Digest]*vtxInfo {
+	fromRegexp := regexp.MustCompile(`^\[.*\] FROM`)
+
+	vtxMap := make(map[digest.Digest]*vtxInfo)
+	for st := range metricsCh {
+		for _, vtx := range st.Vertexes {
+			if _, ok := vtxMap[vtx.Digest]; !ok {
+				vtxMap[vtx.Digest] = &vtxInfo{
+					name: vtx.Name,
+				}
+			}
+			if fromRegexp.MatchString(vtx.Name) {
+				vtxMap[vtx.Digest].from = true
+			}
+			if vtx.Cached {
+				vtxMap[vtx.Digest].cached = true
+			}
+			if vtx.Completed != nil {
+				vtxMap[vtx.Digest].completed = true
+			}
+		}
+	}
+	return vtxMap
+}
+
+func outputCacheMetrics(out *os.File, startTime time.Time, vtxMap map[digest.Digest]*vtxInfo) {
+	metrics := struct {
+		Total            int64 `json:"total"`
+		Completed        int64 `json:"completed"`
+		UserTotal        int64 `json:"user_total"`
+		UserCached       int64 `json:"user_cached"`
+		UserCompleted    int64 `json:"user_completed"`
+		UserCacheable    int64 `json:"user_cacheable"`
+		From             int64 `json:"from"`
+		Miss             int64 `json:"miss"`
+		ClientDurationMS int64 `json:"client_duration_ms"`
+	}{
+		ClientDurationMS: time.Since(startTime).Milliseconds(),
+	}
+	for _, vtx := range vtxMap {
+		metrics.Total++
+		if vtx.completed {
+			metrics.Completed++
+		}
+		if strings.HasPrefix(vtx.name, "[internal]") ||
+			strings.HasPrefix(vtx.name, "[auth]") ||
+			strings.HasPrefix(vtx.name, "importing cache") ||
+			strings.HasPrefix(vtx.name, "exporting ") {
+			continue
+		}
+		metrics.UserTotal++
+		metrics.UserCacheable++
+		if vtx.cached {
+			metrics.UserCached++
+		} else if !vtx.from {
+			metrics.Miss++
+			fmt.Fprintf(out, "cache miss: %s\n", vtx.name)
+		}
+		if vtx.completed {
+			metrics.UserCompleted++
+		}
+		if vtx.from {
+			metrics.From++
+			metrics.UserCacheable--
+		}
+	}
+	dt, _ := json.Marshal(metrics)
+	fmt.Fprintln(out, string(dt))
+}

docs/reference/buildctl.md

@@ -79,6 +79,7 @@ OPTIONS:
    --source-policy-file value        Read source policy file from a JSON file
    --ref-file value                  Write build ref to a file
    --registry-auth-tlscontext value  Overwrite TLS configuration when authenticating with registries, e.g. --registry-auth-tlscontext host=https://myserver:2376,insecure=false,ca=/path/to/my/ca.crt,cert=/path/to/my/cert.crt,key=/path/to/my/key.crt
+   --debug-json-cache-metrics value  Where to output json cache metrics, use 'stdout' or 'stderr' for standard (error) output.
    
 ```
 <!---GENERATE_END-->