deduplicate stack logs and optionally trace write stacks

blockstore/splitstore/debug.go

@@ -1,11 +1,14 @@
 package splitstore
 
 import (
+	"crypto/sha256"
+	"encoding/hex"
 	"fmt"
 	"os"
 	"os/exec"
 	"path/filepath"
 	"runtime/debug"
+	"strings"
 	"sync"
 	"time"
 
@@ -20,11 +23,11 @@ import (
 )
 
 type debugLog struct {
-	basePath                      string
+	readPath, writePath, movePath, stackPath string
-	readPath, writePath, movePath string
+	readMx, writeMx, moveMx, stackMx         sync.Mutex
-	readMx, writeMx, moveMx       sync.Mutex
+	readLog, writeLog, moveLog, stackLog     *os.File
-	readLog, writeLog, moveLog    *os.File
+	readCnt, writeCnt, moveCnt, stackCnt     int
-	readCnt, writeCnt, moveCnt    int
+	stackMap                                 map[string]struct{}
 }
 
 func openDebugLog(path string) (*debugLog, error) {
@@ -55,14 +58,25 @@ func openDebugLog(path string) (*debugLog, error) {
 		return nil, xerrors.Errorf("error opening move log: %w", err)
 	}
 
+	stackPath := filepath.Join(basePath, "stack.log")
+	stackFile, err := os.OpenFile(stackPath, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644)
+	if err != nil {
+		_ = readFile.Close()
+		_ = writeFile.Close()
+		_ = moveFile.Close()
+		return nil, xerrors.Errorf("error opening stack log: %w", err)
+	}
+
 	return &debugLog{
-		basePath:  basePath,
 		readPath:  readPath,
 		writePath: writePath,
 		movePath:  movePath,
+		stackPath: stackPath,
 		readLog:   readFile,
 		writeLog:  writeFile,
 		moveLog:   moveFile,
+		stackLog:  stackFile,
+		stackMap:  make(map[string]struct{}),
 	}, nil
 }
 
@@ -71,7 +85,8 @@ func (d *debugLog) LogReadMiss(curTs *types.TipSet, cid cid.Cid) {
 		return
 	}
 
-	stack := debug.Stack()
+	stack := d.getStack()
+
 	var epoch abi.ChainEpoch
 	if curTs != nil {
 		epoch = curTs.Height()
@@ -82,7 +97,7 @@ func (d *debugLog) LogReadMiss(curTs *types.TipSet, cid cid.Cid) {
 
 	d.readCnt++
 
-	_, err := fmt.Fprintf(d.readLog, "%d %s\n%s\n", epoch, cid, string(stack))
+	_, err := fmt.Fprintf(d.readLog, "%s %d %s %s\n", time.Now(), epoch, cid, stack)
 	if err != nil {
 		log.Warnf("error writing read log: %s", err)
 	}
@@ -93,12 +108,17 @@ func (d *debugLog) LogWrite(curTs *types.TipSet, blk blocks.Block, writeEpoch ab
 		return
 	}
 
+	var stack string
+	if enableDebugLogWriteTraces {
+		stack = " " + d.getStack()
+	}
+
 	d.writeMx.Lock()
 	defer d.writeMx.Unlock()
 
 	d.writeCnt++
 
-	_, err := fmt.Fprintf(d.writeLog, "%d %s %d\n", curTs.Height(), blk.Cid(), writeEpoch)
+	_, err := fmt.Fprintf(d.writeLog, "%s %d %s %d%s\n", time.Now(), curTs.Height(), blk.Cid(), writeEpoch, stack)
 	if err != nil {
 		log.Warnf("error writing write log: %s", err)
 	}
@@ -109,13 +129,19 @@ func (d *debugLog) LogWriteMany(curTs *types.TipSet, blks []blocks.Block, writeE
 		return
 	}
 
+	var stack string
+	if enableDebugLogWriteTraces {
+		stack = " " + d.getStack()
+	}
+
 	d.writeMx.Lock()
 	defer d.writeMx.Unlock()
 
 	d.writeCnt += len(blks)
 
+	now := time.Now()
 	for _, blk := range blks {
-		_, err := fmt.Fprintf(d.writeLog, "%d %s %d\n", curTs.Height(), blk.Cid(), writeEpoch)
+		_, err := fmt.Fprintf(d.writeLog, "%s %d %s %d%s\n", now, curTs.Height(), blk.Cid(), writeEpoch, stack)
 		if err != nil {
 			log.Warnf("error writing write log: %s", err)
 			break
@@ -148,6 +174,7 @@ func (d *debugLog) Flush() {
 	d.rotateReadLog()
 	d.rotateWriteLog()
 	d.rotateMoveLog()
+	d.rotateStackLog()
 }
 
 func (d *debugLog) rotateReadLog() {
@@ -160,13 +187,13 @@ func (d *debugLog) rotateReadLog() {
 
 	err := d.rotate(d.readLog, d.readPath)
 	if err != nil {
-		log.Errorf("error rotating read log: %s", err)
+		log.Warnf("error rotating read log: %s", err)
 		return
 	}
 
 	d.readLog, err = os.OpenFile(d.readPath, os.O_WRONLY|os.O_CREATE, 0644)
 	if err != nil {
-		log.Errorf("error opening log file: %s", err)
+		log.Warnf("error opening log file: %s", err)
 		return
 	}
 
@@ -183,13 +210,13 @@ func (d *debugLog) rotateWriteLog() {
 
 	err := d.rotate(d.writeLog, d.writePath)
 	if err != nil {
-		log.Errorf("error rotating read log: %s", err)
+		log.Warnf("error rotating write log: %s", err)
 		return
 	}
 
 	d.writeLog, err = os.OpenFile(d.writePath, os.O_WRONLY|os.O_CREATE, 0644)
 	if err != nil {
-		log.Errorf("error opening log file: %s", err)
+		log.Warnf("error opening write log file: %s", err)
 		return
 	}
 
@@ -206,19 +233,42 @@ func (d *debugLog) rotateMoveLog() {
 
 	err := d.rotate(d.moveLog, d.movePath)
 	if err != nil {
-		log.Errorf("error rotating read log: %s", err)
+		log.Warnf("error rotating move log: %s", err)
 		return
 	}
 
 	d.moveLog, err = os.OpenFile(d.movePath, os.O_WRONLY|os.O_CREATE, 0644)
 	if err != nil {
-		log.Errorf("error opening log file: %s", err)
+		log.Warnf("error opening move log file: %s", err)
 		return
 	}
 
 	d.moveCnt = 0
 }
 
+func (d *debugLog) rotateStackLog() {
+	d.stackMx.Lock()
+	defer d.stackMx.Unlock()
+
+	if d.stackCnt == 0 {
+		return
+	}
+
+	err := d.rotate(d.stackLog, d.stackPath)
+	if err != nil {
+		log.Warnf("error rotating stack log: %s", err)
+		return
+	}
+
+	d.stackLog, err = os.OpenFile(d.stackPath, os.O_WRONLY|os.O_CREATE, 0644)
+	if err != nil {
+		log.Warnf("error opening stack log file: %s", err)
+		return
+	}
+
+	d.stackCnt = 0
+}
+
 func (d *debugLog) rotate(f *os.File, path string) error {
 	err := f.Close()
 	if err != nil {
@@ -235,7 +285,7 @@ func (d *debugLog) rotate(f *os.File, path string) error {
 		cmd := exec.Command("gzip", arxivPath)
 		err := cmd.Run()
 		if err != nil {
-			log.Errorf("error compressing log: %s", err)
+			log.Warnf("error compressing log: %s", err)
 		}
 	}()
 
@@ -259,5 +309,49 @@ func (d *debugLog) Close() error {
 	err3 := d.moveLog.Close()
 	d.moveMx.Unlock()
 
-	return multierr.Combine(err1, err2, err3)
+	d.stackMx.Lock()
+	err4 := d.stackLog.Close()
+	d.stackMx.Unlock()
+
+	return multierr.Combine(err1, err2, err3, err4)
+}
+
+func (d *debugLog) getStack() string {
+	sk := d.getNormalizedStackTrace()
+	hash := sha256.Sum256([]byte(sk))
+	key := string(hash[:])
+	repr := hex.EncodeToString(hash[:])
+
+	d.stackMx.Lock()
+	_, ok := d.stackMap[key]
+
+	if !ok {
+		_, err := fmt.Fprintf(d.stackLog, "%s\n%s\n", repr, sk)
+		if err != nil {
+			log.Warnf("error writing stack trace: %s", err)
+		}
+	}
+
+	d.stackMap[key] = struct{}{}
+	d.stackCnt++
+	d.stackMx.Unlock()
+
+	return repr
+}
+
+func (d *debugLog) getNormalizedStackTrace() string {
+	sk := string(debug.Stack())
+
+	// Normalization for deduplication
+	// skip first line -- it's the goroutine
+	// for each line that ends in a ), remove the call args -- these are the registers
+	lines := strings.Split(sk, "\n")[1:]
+	for i, line := range lines {
+		if line[len(line)-1] == ')' {
+			idx := strings.LastIndex(line, "(")
+			lines[i] = line[:idx]
+		}
+	}
+
+	return strings.Join(lines, "\n")
 }

blockstore/splitstore/splitstore.go

@@ -77,6 +77,8 @@ var (
 
 	// set this to true if you are debugging the splitstore to enable debug logging
 	enableDebugLog = false
+	// set this to true if you want to track origin stack traces in the write log
+	enableDebugLogWriteTraces = false
 )
 
 const (