diff --git a/blockstore/splitstore/debug.go b/blockstore/splitstore/debug.go index 4c788a28b5b..2be85ebfe8d 100644 --- a/blockstore/splitstore/debug.go +++ b/blockstore/splitstore/debug.go @@ -20,60 +20,58 @@ import ( ) type debugLog struct { - readPath, writePath, deletePath, stackPath string - readMx, writeMx, deleteMx, stackMx sync.Mutex - readLog, writeLog, deleteLog, stackLog *os.File - readCnt, writeCnt, deleteCnt, stackCnt int - stackMap map[string]string + readLog, writeLog, deleteLog, stackLog *debugLogOp + + stackMx sync.Mutex + stackMap map[string]string +} + +type debugLogOp struct { + path string + mx sync.Mutex + log *os.File + count int } func openDebugLog(path string) (*debugLog, error) { basePath := filepath.Join(path, "debug") err := os.MkdirAll(basePath, 0755) if err != nil { - return nil, xerrors.Errorf("error creating debug log directory: %w", err) + return nil, err } - readPath := filepath.Join(basePath, "read.log") - readFile, err := os.OpenFile(readPath, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644) + readLog, err := openDebugLogOp(basePath, "read.log") if err != nil { - return nil, xerrors.Errorf("error opening read log: %w", err) + return nil, err } - writePath := filepath.Join(basePath, "write.log") - writeFile, err := os.OpenFile(writePath, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644) + writeLog, err := openDebugLogOp(basePath, "write.log") if err != nil { - _ = readFile.Close() - return nil, xerrors.Errorf("error opening write log: %w", err) + _ = readLog.Close() + return nil, err } - deletePath := filepath.Join(basePath, "delete.log") - deleteFile, err := os.OpenFile(deletePath, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644) + deleteLog, err := openDebugLogOp(basePath, "delete.log") if err != nil { - _ = readFile.Close() - _ = writeFile.Close() - return nil, xerrors.Errorf("error opening delete log: %w", err) + _ = readLog.Close() + _ = writeLog.Close() + return nil, err } - stackPath := filepath.Join(basePath, "stack.log") - stackFile, err := os.OpenFile(stackPath, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644) + stackLog, err := openDebugLogOp(basePath, "stack.log") if err != nil { - _ = readFile.Close() - _ = writeFile.Close() - _ = deleteFile.Close() + _ = readLog.Close() + _ = writeLog.Close() + _ = deleteLog.Close() return nil, xerrors.Errorf("error opening stack log: %w", err) } return &debugLog{ - readPath: readPath, - writePath: writePath, - deletePath: deletePath, - stackPath: stackPath, - readLog: readFile, - writeLog: writeFile, - deleteLog: deleteFile, - stackLog: stackFile, - stackMap: make(map[string]string), + readLog: readLog, + writeLog: writeLog, + deleteLog: deleteLog, + stackLog: stackLog, + stackMap: make(map[string]string), }, nil } @@ -83,13 +81,7 @@ func (d *debugLog) LogReadMiss(cid cid.Cid) { } stack := d.getStack() - - d.readMx.Lock() - defer d.readMx.Unlock() - - d.readCnt++ - - _, err := fmt.Fprintf(d.readLog, "%s %s %s\n", d.timestamp(), cid, stack) + err := d.readLog.Log("%s %s %s\n", d.timestamp(), cid, stack) if err != nil { log.Warnf("error writing read log: %s", err) } @@ -105,12 +97,7 @@ func (d *debugLog) LogWrite(blk blocks.Block) { stack = " " + d.getStack() } - d.writeMx.Lock() - defer d.writeMx.Unlock() - - d.writeCnt++ - - _, err := fmt.Fprintf(d.writeLog, "%s %s%s\n", d.timestamp(), blk.Cid(), stack) + err := d.writeLog.Log("%s %s%s\n", d.timestamp(), blk.Cid(), stack) if err != nil { log.Warnf("error writing write log: %s", err) } @@ -126,14 +113,9 @@ func (d *debugLog) LogWriteMany(blks []blocks.Block) { stack = " " + d.getStack() } - d.writeMx.Lock() - defer d.writeMx.Unlock() - - d.writeCnt += len(blks) - now := d.timestamp() for _, blk := range blks { - _, err := fmt.Fprintf(d.writeLog, "%s %s%s\n", now, blk.Cid(), stack) + err := d.writeLog.Log("%s %s%s\n", now, blk.Cid(), stack) if err != nil { log.Warnf("error writing write log: %s", err) break @@ -146,14 +128,9 @@ func (d *debugLog) LogDelete(cids []cid.Cid) { return } - d.deleteMx.Lock() - defer d.deleteMx.Unlock() - - d.deleteCnt += len(cids) - now := d.timestamp() for _, c := range cids { - _, err := fmt.Fprintf(d.deleteLog, "%s %s\n", now, c) + err := d.deleteLog.Log("%s %s\n", now, c) if err != nil { log.Warnf("error writing delete log: %s", err) break @@ -167,125 +144,10 @@ func (d *debugLog) Flush() { } // rotate non-empty logs - d.rotateReadLog() - d.rotateWriteLog() - d.rotateDeleteLog() - d.rotateStackLog() -} - -func (d *debugLog) rotateReadLog() { - d.readMx.Lock() - defer d.readMx.Unlock() - - if d.readCnt == 0 { - return - } - - err := d.rotate(d.readLog, d.readPath) - if err != nil { - 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.Warnf("error opening log file: %s", err) - return - } - - d.readCnt = 0 -} - -func (d *debugLog) rotateWriteLog() { - d.writeMx.Lock() - defer d.writeMx.Unlock() - - if d.writeCnt == 0 { - return - } - - err := d.rotate(d.writeLog, d.writePath) - if err != nil { - 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.Warnf("error opening write log file: %s", err) - return - } - - d.writeCnt = 0 -} - -func (d *debugLog) rotateDeleteLog() { - d.deleteMx.Lock() - defer d.deleteMx.Unlock() - - if d.deleteCnt == 0 { - return - } - - err := d.rotate(d.deleteLog, d.deletePath) - if err != nil { - log.Warnf("error rotating delete log: %s", err) - return - } - - d.deleteLog, err = os.OpenFile(d.deletePath, os.O_WRONLY|os.O_CREATE, 0644) - if err != nil { - log.Warnf("error opening delete log file: %s", err) - return - } - - d.deleteCnt = 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 { - return xerrors.Errorf("error closing file: %w", err) - } - - arxivPath := fmt.Sprintf("%s-%d", path, time.Now().Unix()) - err = os.Rename(path, arxivPath) - if err != nil { - return xerrors.Errorf("error moving file: %w", err) - } - - go func() { - cmd := exec.Command("gzip", arxivPath) - err := cmd.Run() - if err != nil { - log.Warnf("error compressing log: %s", err) - } - }() - - return nil + d.readLog.Rotate() + d.writeLog.Rotate() + d.deleteLog.Rotate() + d.stackLog.Rotate() } func (d *debugLog) Close() error { @@ -293,21 +155,10 @@ func (d *debugLog) Close() error { return nil } - d.readMx.Lock() err1 := d.readLog.Close() - d.readMx.Unlock() - - d.writeMx.Lock() err2 := d.writeLog.Close() - d.writeMx.Unlock() - - d.deleteMx.Lock() err3 := d.deleteLog.Close() - d.deleteMx.Unlock() - - d.stackMx.Lock() err4 := d.stackLog.Close() - d.stackMx.Unlock() return multierr.Combine(err1, err2, err3, err4) } @@ -322,9 +173,8 @@ func (d *debugLog) getStack() string { if !ok { repr = hex.EncodeToString(hash[:]) d.stackMap[key] = repr - d.stackCnt++ - _, err := fmt.Fprintf(d.stackLog, "%s\n%s\n", repr, sk) + err := d.stackLog.Log("%s\n%s\n", repr, sk) if err != nil { log.Warnf("error writing stack trace for %s: %s", repr, err) } @@ -358,3 +208,66 @@ func (d *debugLog) timestamp() string { ts, _ := time.Now().MarshalText() return string(ts) } + +func openDebugLogOp(basePath, name string) (*debugLogOp, error) { + path := filepath.Join(basePath, name) + file, err := os.OpenFile(path, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644) + if err != nil { + return nil, xerrors.Errorf("error opening %s: %w", name, err) + } + + return &debugLogOp{path: path, log: file}, nil +} + +func (d *debugLogOp) Close() error { + d.mx.Lock() + defer d.mx.Unlock() + + return d.log.Close() +} + +func (d *debugLogOp) Log(template string, arg ...interface{}) error { + d.mx.Lock() + defer d.mx.Unlock() + + d.count++ + _, err := fmt.Fprintf(d.log, template, arg...) + return err +} + +func (d *debugLogOp) Rotate() { + d.mx.Lock() + defer d.mx.Unlock() + + if d.count == 0 { + return + } + + err := d.log.Close() + if err != nil { + log.Warnf("error closing log (file: %s): %s", d.path, err) + return + } + + arxivPath := fmt.Sprintf("%s-%d", d.path, time.Now().Unix()) + err = os.Rename(d.path, arxivPath) + if err != nil { + log.Warnf("error moving log (file: %s): %s", d.path, err) + return + } + + go func() { + cmd := exec.Command("gzip", arxivPath) + err := cmd.Run() + if err != nil { + log.Warnf("error compressing log (file: %s): %s", arxivPath, err) + } + }() + + d.count = 0 + d.log, err = os.OpenFile(d.path, os.O_WRONLY|os.O_CREATE, 0644) + if err != nil { + log.Warnf("error opening log (file: %s): %s", d.path, err) + return + } +}