chore(ae): add more logging

CHANGELOG.md

@@ -2,6 +2,7 @@ v1.8.6 [unreleased]
 -------------------
 
 -	[#21290](https://github.com/influxdata/influxdb/pull/21290): fix: Anti-Entropy loops endlessly with empty shard
+-	[#21381](https://github.com/influxdata/influxdb/pull/21381): chore(ae): add more logging
 
 v1.8.5 [2021-04-19]
 -------------------

tsdb/engine.go

@@ -78,7 +78,7 @@ type Engine interface {
 	Statistics(tags map[string]string) []models.Statistic
 	LastModified() time.Time
 	DiskSize() int64
-	IsIdle() bool
+	IsIdle(isLogged bool) bool
 	Free() error
 
 	io.WriterTo

tsdb/engine/tsm1/engine.go

@@ -886,19 +886,53 @@ func (e *Engine) LoadMetadataIndex(shardID uint64, index tsdb.Index) error {
 	return nil
 }
 
-// IsIdle returns true if the cache is empty, there are no running compactions and the
-// shard is fully compacted.
-func (e *Engine) IsIdle() bool {
+func (e *Engine) IsIdle(isLogged bool) bool {
+	return e.loggedIsIdle(isLogged)
+}
+
+const logMsg = "IsIdle false because nonzero"
+
+// loggedIsIdle returns true if the cache is empty, there are no running compactions and the
+// shard is fully compacted.  If trace logging is enabled, it logs the reasons why an engine
+// is busy
+func (e *Engine) loggedIsIdle(isLogged bool) bool {
+	const cacheCompactions = "Cache Compactions: "
+	const levelZeroCompactions = "Level Zero Compactions: "
+	const levelOneCompactions = "Level One Compactions: "
+	const levelTwoCompactions = "Level Two Compactions: "
+	const fullCompactions = "Full Compactions: "
+	const optimizeCompactions = "TSM Optimization Compactions: "
+	var log *zap.Logger
+
+	if isLogged {
+		log = e.traceLogger.With(zap.Uint64("ShardId", e.id), zap.String("path", e.path))
+	}
+
 	cacheEmpty := e.Cache.Size() == 0
+	if !cacheEmpty && log != nil {
+		log.Info(logMsg, zap.Uint64("Cache size", e.Cache.Size()))
+	}
 
-	runningCompactions := atomic.LoadInt64(&e.stats.CacheCompactionsActive)
-	runningCompactions += atomic.LoadInt64(&e.stats.TSMCompactionsActive[0])
-	runningCompactions += atomic.LoadInt64(&e.stats.TSMCompactionsActive[1])
-	runningCompactions += atomic.LoadInt64(&e.stats.TSMCompactionsActive[2])
-	runningCompactions += atomic.LoadInt64(&e.stats.TSMFullCompactionsActive)
-	runningCompactions += atomic.LoadInt64(&e.stats.TSMOptimizeCompactionsActive)
+	runningCompactions := logCheckForCompactions(log, &e.stats.CacheCompactionsActive, cacheCompactions)
+	runningCompactions += logCheckForCompactions(log, &e.stats.TSMCompactionsActive[0], levelZeroCompactions)
+	runningCompactions += logCheckForCompactions(log, &e.stats.TSMCompactionsActive[1], levelOneCompactions)
+	runningCompactions += logCheckForCompactions(log, &e.stats.TSMCompactionsActive[2], levelTwoCompactions)
+	runningCompactions += logCheckForCompactions(log, &e.stats.TSMFullCompactionsActive, fullCompactions)
+	runningCompactions += logCheckForCompactions(log, &e.stats.TSMOptimizeCompactionsActive, optimizeCompactions)
+	fullyCompacted := e.CompactionPlan.FullyCompacted()
+	if !fullyCompacted && log != nil {
+		log.Info("IsIdle false because", zap.Bool("FullyCompacted", fullyCompacted))
+	}
 
-	return cacheEmpty && runningCompactions == 0 && e.CompactionPlan.FullyCompacted()
+	return cacheEmpty && runningCompactions == 0 && fullyCompacted
+}
+
+func logCheckForCompactions(log *zap.Logger, counter *int64, fieldName string) int64 {
+	count := atomic.LoadInt64(counter)
+	if count > 0 && log != nil {
+		log.Info(logMsg, zap.Int64(fieldName, count))
+	}
+	return count
 }
 
 // Free releases any resources held by the engine to free up memory or CPU.

tsdb/shard.go

@@ -452,7 +452,16 @@ func (s *Shard) IsIdle() bool {
 	if err != nil {
 		return true
 	}
-	return engine.IsIdle()
+	return engine.IsIdle(false)
+}
+
+// IsIdle return true if the shard is not receiving writes and is fully compacted.
+func (s *Shard) LoggedIsIdle() bool {
+	engine, err := s.Engine()
+	if err != nil {
+		return true
+	}
+	return engine.IsIdle(true)
 }
 
 func (s *Shard) Free() error {
@@ -1200,15 +1209,15 @@ func (s *Shard) TagKeyCardinality(name, key []byte) int {
 }
 
 // Digest returns a digest of the shard.
-func (s *Shard) Digest() (io.ReadCloser, int64, error) {
+func (s *Shard) Digest(isLogged bool) (io.ReadCloser, int64, error) {
 	engine, err := s.Engine()
 	if err != nil {
 		return nil, 0, err
 	}
 
 	// Make sure the shard is idle/cold. (No use creating a digest of a
 	// hot shard that is rapidly changing.)
-	if !engine.IsIdle() {
+	if !engine.IsIdle(isLogged) {
 		return nil, 0, ErrShardNotIdle
 	}
 

tsdb/store.go

@@ -593,7 +593,7 @@ func (s *Store) ShardDigest(id uint64) (io.ReadCloser, int64, error) {
 		return nil, 0, ErrShardNotFound
 	}
 
-	return sh.Digest()
+	return sh.Digest(false)
 }
 
 // CreateShard creates a shard with the given id and retention policy on a database.