cmd/go: add README and access log to cache directory

The README is there to help people who stumble across the directory.

The access log is there to help us evaluate potential algorithms for
managing and pruning cache directories. For now the management
is manual: users have to run "go clean -cache" if they want the cache
to get smaller.

As a low-resolution version of the access log, we also update the
mtime on each cache file as they are used by the go command.
A simple refinement of go clean -cache would be to delete
(perhaps automatically) cache files that have not been used in more
than one day, or some suitable time period.

Change-Id: I1dd6309952942169d71256c4b50b723583d21fca
Reviewed-on: https://go-review.googlesource.com/75471
Run-TryBot: Russ Cox <rsc@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
Reviewed-by: David Crawshaw <crawshaw@golang.org>

src/cmd/dist/deps.go

@@ -100,6 +100,7 @@ var builddeps = map[string][]string{
 		"strconv",              // cmd/go/internal/cache
 		"strings",              // cmd/go/internal/cache
 		"sync",                 // cmd/go/internal/cache
+		"time",                 // cmd/go/internal/cache
 	},
 
 	"cmd/go/internal/cfg": {

src/cmd/go/internal/cache/cache.go

@@ -17,6 +17,7 @@ import (
 	"path/filepath"
 	"strconv"
 	"strings"
+	"time"
 )
 
 // An ActionID is a cache action key, the hash of a complete description of a
@@ -30,6 +31,8 @@ type OutputID [HashSize]byte
 // A Cache is a package cache, backed by a file system directory tree.
 type Cache struct {
 	dir string
+	log *os.File
+	now func() time.Time
 }
 
 // Open opens and returns the cache in the given directory.
@@ -58,7 +61,15 @@ func Open(dir string) (*Cache, error) {
 			return nil, err
 		}
 	}
-	c := &Cache{dir: dir}
+	f, err := os.OpenFile(filepath.Join(dir, "log.txt"), os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0666)
+	if err != nil {
+		return nil, err
+	}
+	c := &Cache{
+		dir: dir,
+		log: f,
+		now: time.Now,
+	}
 	return c, nil
 }
 
@@ -116,7 +127,7 @@ func (c *Cache) Get(id ActionID) (OutputID, int64, error) {
 // get is Get but does not respect verify mode, so that Put can use it.
 func (c *Cache) get(id ActionID) (OutputID, int64, error) {
 	missing := func() (OutputID, int64, error) {
-		// TODO: log miss
+		fmt.Fprintf(c.log, "%d miss %x\n", c.now().Unix(), id)
 		return OutputID{}, 0, errMissing
 	}
 	f, err := os.Open(c.fileName(id, "a"))
@@ -148,8 +159,11 @@ func (c *Cache) get(id ActionID) (OutputID, int64, error) {
 		return missing()
 	}
 
-	// TODO: Update modtime of f to give a signal about recently used?
-	// TODO: log hit
+	fmt.Fprintf(c.log, "%d get %x\n", c.now().Unix(), id)
+
+	// Best-effort attempt to update mtime on file,
+	// so that mtime reflects cache access time.
+	os.Chtimes(c.fileName(id, "a"), c.now(), c.now())
 
 	return buf, size, nil
 }
@@ -171,7 +185,13 @@ func (c *Cache) GetBytes(id ActionID) ([]byte, error) {
 
 // OutputFile returns the name of the cache file storing output with the given OutputID.
 func (c *Cache) OutputFile(out OutputID) string {
-	return c.fileName(out, "d")
+	file := c.fileName(out, "d")
+
+	// Best-effort attempt to update mtime on file,
+	// so that mtime reflects cache access time.
+	os.Chtimes(file, c.now(), c.now())
+
+	return file
 }
 
 // putIndexEntry adds an entry to the cache recording that executing the action
@@ -197,7 +217,14 @@ func (c *Cache) putIndexEntry(id ActionID, out OutputID, size int64) error {
 			panic("cache verify failed")
 		}
 	}
-	return ioutil.WriteFile(c.fileName(id, "a"), entry, 0666)
+	file := c.fileName(id, "a")
+	if err := ioutil.WriteFile(file, entry, 0666); err != nil {
+		os.Remove(file)
+		return err
+	}
+
+	fmt.Fprintf(c.log, "%d put %x %x %d\n", c.now().Unix(), id, out, size)
+	return nil
 }
 
 // Put stores the given output in the cache as the output for the action ID.
@@ -221,7 +248,6 @@ func (c *Cache) Put(id ActionID, file io.ReadSeeker) (OutputID, int64, error) {
 	}
 
 	// Add to cache index.
-	// TODO: log put
 	return out, size, c.putIndexEntry(id, out, size)
 }
 

src/cmd/go/internal/cache/cache_test.go

@@ -10,6 +10,7 @@ import (
 	"os"
 	"path/filepath"
 	"testing"
+	"time"
 )
 
 func init() {
@@ -141,6 +142,55 @@ func TestVerifyPanic(t *testing.T) {
 	t.Fatal("mismatched Put did not panic in verify mode")
 }
 
+func TestCacheLog(t *testing.T) {
+	dir, err := ioutil.TempDir("", "cachetest-")
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer os.RemoveAll(dir)
+
+	c, err := Open(dir)
+	if err != nil {
+		t.Fatalf("Open: %v", err)
+	}
+	c.now = func() time.Time { return time.Unix(1e9, 0) }
+
+	id := ActionID(dummyID(1))
+	c.Get(id)
+	c.PutBytes(id, []byte("abc"))
+	c.Get(id)
+
+	c, err = Open(dir)
+	if err != nil {
+		t.Fatalf("Open #2: %v", err)
+	}
+	c.now = func() time.Time { return time.Unix(1e9+1, 0) }
+	c.Get(id)
+
+	id2 := ActionID(dummyID(2))
+	c.Get(id2)
+	c.PutBytes(id2, []byte("abc"))
+	c.Get(id2)
+	c.Get(id)
+
+	data, err := ioutil.ReadFile(filepath.Join(dir, "log.txt"))
+	if err != nil {
+		t.Fatal(err)
+	}
+	want := `1000000000 miss 0100000000000000000000000000000000000000000000000000000000000000
+1000000000 put 0100000000000000000000000000000000000000000000000000000000000000 ba7816bf8f01cfea414140de5dae2223b00361a396177a9cb410ff61f20015ad 3
+1000000000 get 0100000000000000000000000000000000000000000000000000000000000000
+1000000001 get 0100000000000000000000000000000000000000000000000000000000000000
+1000000001 miss 0200000000000000000000000000000000000000000000000000000000000000
+1000000001 put 0200000000000000000000000000000000000000000000000000000000000000 ba7816bf8f01cfea414140de5dae2223b00361a396177a9cb410ff61f20015ad 3
+1000000001 get 0200000000000000000000000000000000000000000000000000000000000000
+1000000001 get 0100000000000000000000000000000000000000000000000000000000000000
+`
+	if string(data) != want {
+		t.Fatalf("log:\n%s\nwant:\n%s", string(data), want)
+	}
+}
+
 func dummyID(x int) [HashSize]byte {
 	var out [HashSize]byte
 	binary.LittleEndian.PutUint64(out[:], uint64(x))

src/cmd/go/internal/cache/default.go

@@ -6,6 +6,7 @@ package cache
 
 import (
 	"cmd/go/internal/base"
+	"io/ioutil"
 	"os"
 	"path/filepath"
 	"runtime"
@@ -23,6 +24,14 @@ var (
 	defaultCache *Cache
 )
 
+// cacheREADME is a message stored in a README in the cache directory.
+// Because the cache lives outside the normal Go trees, we leave the
+// README as a courtesy to explain where it came from.
+const cacheREADME = `This directory holds cached build artifacts from the Go build system.
+Run "go clean -cache" if the directory is getting too large.
+See golang.org to learn more about Go.
+`
+
 // initDefaultCache does the work of finding the default cache
 // the first time Default is called.
 func initDefaultCache() {
@@ -33,6 +42,11 @@ func initDefaultCache() {
 	if err := os.MkdirAll(dir, 0777); err != nil {
 		base.Fatalf("initializing cache in $GOCACHE: %s", err)
 	}
+	if _, err := os.Stat(filepath.Join(dir, "README")); err != nil {
+		// Best effort.
+		ioutil.WriteFile(filepath.Join(dir, "README"), []byte(cacheREADME), 0666)
+	}
+
 	c, err := Open(dir)
 	if err != nil {
 		base.Fatalf("initializing cache in $GOCACHE: %s", err)