clean up: simplify debug log, get rid of ugly debug log

blockstore/splitstore/debug.go

@@ -15,19 +15,16 @@ import (
 	"go.uber.org/multierr"
 	"golang.org/x/xerrors"
 
-	"github.com/filecoin-project/go-state-types/abi"
-	"github.com/filecoin-project/lotus/chain/types"
-
 	blocks "github.com/ipfs/go-block-format"
 	cid "github.com/ipfs/go-cid"
 )
 
 type debugLog struct {
-	readPath, writePath, movePath, stackPath string
+	readPath, writePath, deletePath, stackPath string
-	readMx, writeMx, moveMx, stackMx         sync.Mutex
+	readMx, writeMx, deleteMx, stackMx         sync.Mutex
-	readLog, writeLog, moveLog, stackLog     *os.File
+	readLog, writeLog, deleteLog, stackLog     *os.File
-	readCnt, writeCnt, moveCnt, stackCnt     int
+	readCnt, writeCnt, deleteCnt, stackCnt     int
-	stackMap                                 map[string]string
+	stackMap                                   map[string]string
 }
 
 func openDebugLog(path string) (*debugLog, error) {
@@ -50,12 +47,12 @@ func openDebugLog(path string) (*debugLog, error) {
 		return nil, xerrors.Errorf("error opening write log: %w", err)
 	}
 
-	movePath := filepath.Join(basePath, "move.log")
+	deletePath := filepath.Join(basePath, "delete.log")
-	moveFile, err := os.OpenFile(movePath, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644)
+	deleteFile, err := os.OpenFile(deletePath, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644)
 	if err != nil {
 		_ = readFile.Close()
 		_ = writeFile.Close()
-		return nil, xerrors.Errorf("error opening move log: %w", err)
+		return nil, xerrors.Errorf("error opening delete log: %w", err)
 	}
 
 	stackPath := filepath.Join(basePath, "stack.log")
@@ -63,47 +60,42 @@ func openDebugLog(path string) (*debugLog, error) {
 	if err != nil {
 		_ = readFile.Close()
 		_ = writeFile.Close()
-		_ = moveFile.Close()
+		_ = deleteFile.Close()
 		return nil, xerrors.Errorf("error opening stack log: %w", err)
 	}
 
 	return &debugLog{
-		readPath:  readPath,
+		readPath:   readPath,
-		writePath: writePath,
+		writePath:  writePath,
-		movePath:  movePath,
+		deletePath: deletePath,
-		stackPath: stackPath,
+		stackPath:  stackPath,
-		readLog:   readFile,
+		readLog:    readFile,
-		writeLog:  writeFile,
+		writeLog:   writeFile,
-		moveLog:   moveFile,
+		deleteLog:  deleteFile,
-		stackLog:  stackFile,
+		stackLog:   stackFile,
-		stackMap:  make(map[string]string),
+		stackMap:   make(map[string]string),
 	}, nil
 }
 
-func (d *debugLog) LogReadMiss(curTs *types.TipSet, cid cid.Cid) {
+func (d *debugLog) LogReadMiss(cid cid.Cid) {
 	if d == nil {
 		return
 	}
 
 	stack := d.getStack()
 
-	var epoch abi.ChainEpoch
-	if curTs != nil {
-		epoch = curTs.Height()
-	}
-
 	d.readMx.Lock()
 	defer d.readMx.Unlock()
 
 	d.readCnt++
 
-	_, err := fmt.Fprintf(d.readLog, "%s %d %s %s\n", d.timestamp(), epoch, cid, stack)
+	_, err := fmt.Fprintf(d.readLog, "%s %s %s\n", d.timestamp(), cid, stack)
 	if err != nil {
 		log.Warnf("error writing read log: %s", err)
 	}
 }
 
-func (d *debugLog) LogWrite(curTs *types.TipSet, blk blocks.Block, writeEpoch abi.ChainEpoch) {
+func (d *debugLog) LogWrite(blk blocks.Block) {
 	if d == nil {
 		return
 	}
@@ -113,23 +105,18 @@ func (d *debugLog) LogWrite(curTs *types.TipSet, blk blocks.Block, writeEpoch ab
 		stack = " " + d.getStack()
 	}
 
-	var curEpoch abi.ChainEpoch
-	if curTs != nil {
-		curEpoch = curTs.Height()
-	}
-
 	d.writeMx.Lock()
 	defer d.writeMx.Unlock()
 
 	d.writeCnt++
 
-	_, err := fmt.Fprintf(d.writeLog, "%s %d %s %d%s\n", d.timestamp(), curEpoch, blk.Cid(), writeEpoch, stack)
+	_, err := fmt.Fprintf(d.writeLog, "%s %s%s\n", d.timestamp(), blk.Cid(), stack)
 	if err != nil {
 		log.Warnf("error writing write log: %s", err)
 	}
 }
 
-func (d *debugLog) LogWriteMany(curTs *types.TipSet, blks []blocks.Block, writeEpoch abi.ChainEpoch) {
+func (d *debugLog) LogWriteMany(blks []blocks.Block) {
 	if d == nil {
 		return
 	}
@@ -139,11 +126,6 @@ func (d *debugLog) LogWriteMany(curTs *types.TipSet, blks []blocks.Block, writeE
 		stack = " " + d.getStack()
 	}
 
-	var curEpoch abi.ChainEpoch
-	if curTs != nil {
-		curEpoch = curTs.Height()
-	}
-
 	d.writeMx.Lock()
 	defer d.writeMx.Unlock()
 
@@ -151,7 +133,7 @@ func (d *debugLog) LogWriteMany(curTs *types.TipSet, blks []blocks.Block, writeE
 
 	now := d.timestamp()
 	for _, blk := range blks {
-		_, err := fmt.Fprintf(d.writeLog, "%s %d %s %d%s\n", now, curEpoch, blk.Cid(), writeEpoch, stack)
+		_, err := fmt.Fprintf(d.writeLog, "%s %s%s\n", now, blk.Cid(), stack)
 		if err != nil {
 			log.Warnf("error writing write log: %s", err)
 			break
@@ -159,19 +141,23 @@ func (d *debugLog) LogWriteMany(curTs *types.TipSet, blks []blocks.Block, writeE
 	}
 }
 
-func (d *debugLog) LogMove(curTs *types.TipSet, cid cid.Cid) {
+func (d *debugLog) LogDelete(cids []cid.Cid) {
 	if d == nil {
 		return
 	}
 
-	d.moveMx.Lock()
+	d.deleteMx.Lock()
-	defer d.moveMx.Unlock()
+	defer d.deleteMx.Unlock()
 
-	d.moveCnt++
+	d.deleteCnt += len(cids)
 
-	_, err := fmt.Fprintf(d.moveLog, "%d %s\n", curTs.Height(), cid)
+	now := d.timestamp()
-	if err != nil {
+	for _, c := range cids {
-		log.Warnf("error writing move log: %s", err)
+		_, err := fmt.Fprintf(d.deleteLog, "%s %s\n", now, c)
+		if err != nil {
+			log.Warnf("error writing delete log: %s", err)
+			break
+		}
 	}
 }
 
@@ -183,7 +169,7 @@ func (d *debugLog) Flush() {
 	// rotate non-empty logs
 	d.rotateReadLog()
 	d.rotateWriteLog()
-	d.rotateMoveLog()
+	d.rotateDeleteLog()
 	d.rotateStackLog()
 }
 
@@ -233,27 +219,27 @@ func (d *debugLog) rotateWriteLog() {
 	d.writeCnt = 0
 }
 
-func (d *debugLog) rotateMoveLog() {
+func (d *debugLog) rotateDeleteLog() {
-	d.moveMx.Lock()
+	d.deleteMx.Lock()
-	defer d.moveMx.Unlock()
+	defer d.deleteMx.Unlock()
 
-	if d.moveCnt == 0 {
+	if d.deleteCnt == 0 {
 		return
 	}
 
-	err := d.rotate(d.moveLog, d.movePath)
+	err := d.rotate(d.deleteLog, d.deletePath)
 	if err != nil {
-		log.Warnf("error rotating move log: %s", err)
+		log.Warnf("error rotating delete log: %s", err)
 		return
 	}
 
-	d.moveLog, err = os.OpenFile(d.movePath, os.O_WRONLY|os.O_CREATE, 0644)
+	d.deleteLog, err = os.OpenFile(d.deletePath, os.O_WRONLY|os.O_CREATE, 0644)
 	if err != nil {
-		log.Warnf("error opening move log file: %s", err)
+		log.Warnf("error opening delete log file: %s", err)
 		return
 	}
 
-	d.moveCnt = 0
+	d.deleteCnt = 0
 }
 
 func (d *debugLog) rotateStackLog() {
@@ -315,9 +301,9 @@ func (d *debugLog) Close() error {
 	err2 := d.writeLog.Close()
 	d.writeMx.Unlock()
 
-	d.moveMx.Lock()
+	d.deleteMx.Lock()
-	err3 := d.moveLog.Close()
+	err3 := d.deleteLog.Close()
-	d.moveMx.Unlock()
+	d.deleteMx.Unlock()
 
 	d.stackMx.Lock()
 	err4 := d.stackLog.Close()

blockstore/splitstore/splitstore.go

@@ -25,7 +25,6 @@ import (
 	"github.com/filecoin-project/lotus/build"
 	"github.com/filecoin-project/lotus/chain/types"
 	"github.com/filecoin-project/lotus/metrics"
-	"github.com/filecoin-project/specs-actors/v2/actors/builtin"
 
 	"go.opencensus.io/stats"
 )
@@ -120,7 +119,6 @@ type SplitStore struct {
 
 	baseEpoch   abi.ChainEpoch
 	warmupEpoch abi.ChainEpoch
-	writeEpoch  abi.ChainEpoch // for debug logging only
 
 	coldPurgeSize int
 
@@ -234,10 +232,9 @@ func (s *SplitStore) Get(cid cid.Cid) (blocks.Block, error) {
 		if s.debug != nil {
 			s.mx.Lock()
 			warm := s.warmupEpoch > 0
-			curTs := s.curTs
 			s.mx.Unlock()
 			if warm {
-				s.debug.LogReadMiss(curTs, cid)
+				s.debug.LogReadMiss(cid)
 			}
 		}
 
@@ -268,10 +265,9 @@ func (s *SplitStore) GetSize(cid cid.Cid) (int, error) {
 		if s.debug != nil {
 			s.mx.Lock()
 			warm := s.warmupEpoch > 0
-			curTs := s.curTs
 			s.mx.Unlock()
 			if warm {
-				s.debug.LogReadMiss(curTs, cid)
+				s.debug.LogReadMiss(cid)
 			}
 		}
 
@@ -292,13 +288,8 @@ func (s *SplitStore) Put(blk blocks.Block) error {
 
 	err := s.hot.Put(blk)
 	if err == nil {
-		if s.debug != nil {
+		s.debug.LogWrite(blk)
-			s.mx.Lock()
+
-			curTs := s.curTs
-			writeEpoch := s.writeEpoch
-			s.mx.Unlock()
-			s.debug.LogWrite(curTs, blk, writeEpoch)
-		}
 		err = s.trackTxnRef(blk.Cid())
 	}
 
@@ -316,13 +307,7 @@ func (s *SplitStore) PutMany(blks []blocks.Block) error {
 
 	err := s.hot.PutMany(blks)
 	if err == nil {
-		if s.debug != nil {
+		s.debug.LogWriteMany(blks)
-			s.mx.Lock()
-			curTs := s.curTs
-			writeEpoch := s.writeEpoch
-			s.mx.Unlock()
-			s.debug.LogWriteMany(curTs, blks, writeEpoch)
-		}
 
 		err = s.trackTxnRefMany(batch)
 	}
@@ -383,10 +368,9 @@ func (s *SplitStore) View(cid cid.Cid, cb func([]byte) error) error {
 		if s.debug != nil {
 			s.mx.Lock()
 			warm := s.warmupEpoch > 0
-			curTs := s.curTs
 			s.mx.Unlock()
 			if warm {
-				s.debug.LogReadMiss(curTs, cid)
+				s.debug.LogReadMiss(cid)
 			}
 		}
 
@@ -458,10 +442,6 @@ func (s *SplitStore) Start(chain ChainAccessor) error {
 
 	log.Infow("starting splitstore", "baseEpoch", s.baseEpoch, "warmupEpoch", s.warmupEpoch)
 
-	if s.debug != nil {
-		go s.background()
-	}
-
 	// watch the chain
 	chain.SubscribeHeadChanges(s.HeadChange)
 
@@ -525,46 +505,6 @@ func (s *SplitStore) HeadChange(_, apply []*types.TipSet) error {
 	return nil
 }
 
-// this is only used when debug logging is enabled
-func (s *SplitStore) background() {
-	ticker := time.NewTicker(time.Second)
-	defer ticker.Stop()
-
-	for {
-		select {
-		case <-s.ctx.Done():
-			return
-
-		case <-ticker.C:
-			s.updateWriteEpoch()
-		}
-	}
-}
-
-// this is only used when debug logging is enabled
-func (s *SplitStore) updateWriteEpoch() {
-	s.mx.Lock()
-	defer s.mx.Unlock()
-
-	curTs := s.curTs
-	timestamp := time.Unix(int64(curTs.MinTimestamp()), 0)
-
-	dt := time.Since(timestamp)
-	if dt < 0 {
-		writeEpoch := curTs.Height() + 1
-		if writeEpoch > s.writeEpoch {
-			s.writeEpoch = writeEpoch
-		}
-
-		return
-	}
-
-	writeEpoch := curTs.Height() + abi.ChainEpoch(dt.Seconds())/builtin.EpochDurationSeconds + 1
-	if writeEpoch > s.writeEpoch {
-		s.writeEpoch = writeEpoch
-	}
-}
-
 // transactionally protect a reference to an object
 func (s *SplitStore) trackTxnRef(c cid.Cid) error {
 	if !s.txnActive {
@@ -1426,7 +1366,6 @@ func (s *SplitStore) purge(curTs *types.TipSet, cids []cid.Cid) error {
 				}
 
 				deadCids = append(deadCids, c)
-				s.debug.LogMove(curTs, c)
 			}
 
 			err := s.hot.DeleteMany(deadCids)
@@ -1434,6 +1373,8 @@ func (s *SplitStore) purge(curTs *types.TipSet, cids []cid.Cid) error {
 				return xerrors.Errorf("error purging cold objects: %w", err)
 			}
 
+			s.debug.LogDelete(deadCids)
+
 			purgeCnt += len(deadCids)
 			return nil
 		})