trying to figure out why occationally dce doesn't seem to be cached correctly

Author: grantnelson-wf

build/build.go

@@ -1111,38 +1111,11 @@ func (s *Session) LoadPackages(pkg *PackageData) (*sources.Sources, error) {
 		FileSet:    fileSet,
 		JSFiles:    append(pkg.JSFiles, overlayJsFiles...),
 	}
+	s.readDeclCache(pkg)
 
 	// Add the sources to the session's sources map.
 	s.sources[pkg.ImportPath] = srcs
 
-	// Try to load the cached decls from the build cache.
-	if s.buildCache != nil && !pkg.NoCache {
-		declCache := &compiler.DeclCache{}
-
-		// If none of the dependencies were stale, then try to populate the cache.
-		// Calculate the most recent mod time of the package's sources
-		// and the gopherjs executable.
-		// If the cache is older than that or fails to load, then the cache is stale.
-		if !pkg.StaleCache {
-			var srcModTime time.Time
-			if exeModTime := getExeModTime(); exeModTime.After(srcModTime) {
-				srcModTime = exeModTime
-			}
-			if fileModTime := pkg.FileModTime(); fileModTime.After(srcModTime) {
-				srcModTime = fileModTime
-			}
-
-			if !s.buildCache.Load(declCache, pkg.ImportPath, srcModTime) {
-				pkg.StaleCache = true
-				// set a new empty declCache incase the Load left it in a
-				// partially filled state.
-				declCache = &compiler.DeclCache{}
-			}
-		}
-
-		s.cachedDecls[pkg.ImportPath] = declCache
-	}
-
 	// Import dependencies from the augmented files,
 	// whilst skipping any that have been already imported.
 	for _, importedPkgPath := range srcs.UnresolvedImports(pkg.Imports...) {
@@ -1155,6 +1128,48 @@ func (s *Session) LoadPackages(pkg *PackageData) (*sources.Sources, error) {
 	return srcs, nil
 }
 
+// readDeclCache tries to load the cached decls from the build cache
+// for the given package.
+func (s *Session) readDeclCache(pkg *PackageData) {
+	if s.buildCache == nil {
+		return // Caching is disabled for this build
+	}
+
+	if pkg.NoCache {
+		log.Infof(`Cache disabled for package %q`, pkg.ImportPath)
+		return
+	}
+
+	if pkg.StaleCache {
+		s.cachedDecls[pkg.ImportPath] = &compiler.DeclCache{}
+		log.Infof(`Cache stale for package %q`, pkg.ImportPath)
+		return
+	}
+
+	// Since none of the dependencies were stale, try to populate the cache.
+	// Calculate the most recent mod time of the package's sources
+	// and the gopherjs executable.
+	// If the cache is older than that or fails to load, then the cache is stale.
+	var srcModTime time.Time
+	if exeModTime := getExeModTime(); exeModTime.After(srcModTime) {
+		srcModTime = exeModTime
+	}
+	if fileModTime := pkg.FileModTime(); fileModTime.After(srcModTime) {
+		srcModTime = fileModTime
+	}
+
+	declCache := &compiler.DeclCache{}
+	if !s.buildCache.Load(declCache, pkg.ImportPath, srcModTime) {
+		// Load failed so this cache is stale and any package depending on this
+		// package will also be considered stale.
+		pkg.StaleCache = true
+		// set a new empty declCache incase the Load left the declCache in a
+		// partially filled state.
+		declCache = &compiler.DeclCache{}
+	}
+	s.cachedDecls[pkg.ImportPath] = declCache
+}
+
 // PrepareAndCompilePackages prepares and compiles all packages in the session.
 // Thia assumes that all packages including dependencies have already been loaded already.
 // This will return the compiled archive for the rootSrcs package.
@@ -1175,6 +1190,8 @@ func (s *Session) PrepareAndCompilePackages(rootSrcs *sources.Sources) (*compile
 		}
 	}
 
+	log.Infof(`DeclCache stats: %s, [global]`, compiler.GlobalDeclCacheStats())
+
 	rootArchive, ok := s.UpToDateArchives[rootSrcs.ImportPath]
 	if !ok {
 		// This is confirmation that the root package is in the sources map and got compiled.
@@ -1205,9 +1222,12 @@ func (s *Session) CompilePackage(srcs *sources.Sources, tContext *types.Context)
 	// Skip storing cache if the sources haven't changed since read from cache
 	// or the cache is disabled for this package (i.e. `dc` is nil).
 	if s.buildCache != nil {
-		if dc := s.cachedDecls[srcs.ImportPath]; dc != nil && dc.Changed() {
+		dc := s.cachedDecls[srcs.ImportPath]
+		if dc != nil && dc.Changed() {
 			s.buildCache.Store(dc, srcs.ImportPath, time.Now())
 		}
+		// Uncomment to get statics for individual packages cache usage.
+		// log.Infof(`DeclCache stats: %s, %q`, dc.String(), srcs.ImportPath)
 	}
 
 	s.UpToDateArchives[srcs.ImportPath] = archive

compiler/declCache.go

@@ -3,11 +3,26 @@ package compiler
 import (
 	"fmt"
 	"sort"
+	"time"
 )
 
 type DeclCache struct {
 	decls   map[string]*Decl
 	changed bool
+	stats   declCacheStats
+}
+
+var declCacheGlobalStats declCacheStats
+
+type declCacheStats struct {
+	reads        int // number of times Read was called (should be 0 or 1 unless global)
+	writes       int // number of times Write was called (should be 0 or 1 unless global)
+	loadedCount  int // number of declarations loaded from storage
+	addedCount   int // number of declarations added to the cache
+	skippedCount int // number of declarations not cached (for being generic or non-unique)
+	usedCount    int // number of times a declaration was retrieved from the cache
+	readDur      time.Duration
+	writeDur     time.Duration
 }
 
 // Chacnged reports whether the cache has had declarations added to it since
@@ -25,7 +40,12 @@ func (dc *DeclCache) GetDecl(fullname string) *Decl {
 	if dc == nil {
 		return nil // cache is disabled
 	}
-	return dc.decls[fullname]
+	if decl, ok := dc.decls[fullname]; ok {
+		dc.stats.usedCount++
+		declCacheGlobalStats.usedCount++
+		return decl
+	}
+	return nil
 }
 
 func (dc *DeclCache) PutDecl(decl *Decl) {
@@ -44,32 +64,49 @@ func (dc *DeclCache) PutDecl(decl *Decl) {
 		// Therefore, if the package depending on this one changes a type from
 		// being blocking to non-blocking or vice versa, the cached declaration
 		// may be invalid.
+		//
+		// TODO(grantnelson-wf): We could improve this by tracking which packages
+		// the type arguments come from and allow caching if those are all from
+		// dependencies. Since we don't use cache when a dependency changes,
+		// (i.e. has stale cache) we can use generics in that case. We just can't
+		// cache the instantiations that come from packages depending on this one
+		// since those don't invalidate dependent packages' caches.
+		dc.stats.skippedCount++
+		declCacheGlobalStats.skippedCount++
 		return
 	}
 
-	if isUnqueDeclFullName(decl.FullName) {
+	if !isUniqueDeclFullName(decl.FullName) {
 		// Only cache declarations with unique names.
+		dc.stats.skippedCount++
+		declCacheGlobalStats.skippedCount++
 		return
 	}
 
-	if dc.decls == nil {
-		dc.decls = map[string]*Decl{}
-	}
 	if existing, ok := dc.decls[decl.FullName]; ok {
 		if existing != decl {
 			panic(fmt.Errorf(`decl cache conflict: different decls with same name: %q`, decl.FullName))
 		}
 		return
 	}
+
+	if dc.decls == nil {
+		dc.decls = map[string]*Decl{}
+	}
 	dc.decls[decl.FullName] = decl
 	dc.changed = true
+	dc.stats.addedCount++
+	declCacheGlobalStats.addedCount++
 }
 
 func (dc *DeclCache) Read(decode func(any) error) error {
 	if dc == nil {
 		return nil // cache is disabled
 	}
 
+	dc.stats.reads++
+	declCacheGlobalStats.reads++
+	start := time.Now()
 	var count int
 	if err := decode(&count); err != nil {
 		return err
@@ -83,12 +120,18 @@ func (dc *DeclCache) Read(decode func(any) error) error {
 		if err := decode(decl); err != nil {
 			return err
 		}
-		if decl.ForGeneric || isUnqueDeclFullName(decl.FullName) {
+		if decl.ForGeneric || !isUniqueDeclFullName(decl.FullName) {
 			// These declarations should not have been cached.
 			continue
 		}
 		dc.decls[decl.FullName] = decl
 	}
+
+	dc.stats.loadedCount += len(dc.decls)
+	declCacheGlobalStats.loadedCount += len(dc.decls)
+	dur := time.Since(start)
+	dc.stats.readDur += dur
+	declCacheGlobalStats.readDur += dur
 	return nil
 }
 
@@ -97,6 +140,9 @@ func (dc *DeclCache) Write(encode func(any) error) error {
 		return nil // cache is disabled
 	}
 
+	dc.stats.writes++
+	declCacheGlobalStats.writes++
+	start := time.Now()
 	count := len(dc.decls)
 	if err := encode(count); err != nil {
 		return err
@@ -113,5 +159,28 @@ func (dc *DeclCache) Write(encode func(any) error) error {
 			return err
 		}
 	}
+	dur := time.Since(start)
+	dc.stats.writeDur += dur
+	declCacheGlobalStats.writeDur += dur
 	return nil
 }
+
+func (dc *DeclCache) String() string {
+	if dc == nil {
+		return `[disabled]`
+	}
+	return dc.stats.String()
+}
+
+func (s declCacheStats) String() string {
+	return fmt.Sprintf(`reads=%d, writes=%d, `+
+		`loaded=%d, added=%d, skipped=%d, used=%d, `+
+		`readDur=%s, writeDur=%s`,
+		s.reads, s.writes,
+		s.loadedCount, s.addedCount, s.skippedCount, s.usedCount,
+		s.readDur.String(), s.writeDur.String())
+}
+
+func GlobalDeclCacheStats() string {
+	return declCacheGlobalStats.String()
+}

compiler/declNames.go

@@ -133,15 +133,16 @@ func declFullNameDiscriminator(pos token.Pos, fSet *token.FileSet) string {
 	return fmt.Sprintf("@%s:%d:%d", fileName, p.Line, p.Column)
 }
 
-// isUnqueDeclFullName reports whether the given declaration full name is unique.
+// isUniqueDeclFullName reports whether the given declaration full name is unique.
 // A unique declaration name can be safely cached and reused.
-func isUnqueDeclFullName(name string) bool {
+func isUniqueDeclFullName(name string) bool {
 	switch name {
 	case ``, varDeclNotUniqueFullName, funcVarDeclNotUniqueFullName,
 		mainFuncDeclNotUniqueFullName, funcDeclNotUniqueFullName:
 		return false // not unique since it equals one of the known non-unique names
 	}
 
-	// Check if the name is for a nested type declaration without a position discriminator.
+	// If the name is for a nested type declaration without a position discriminator,
+	// then it is not unique, otherwise it should be unique.
 	return !strings.HasPrefix(name, typeDeclNestedPrefix) || strings.Contains(name, "@")
 }