lotus/blockstore/splitstore/debug.go

273 lines
5.2 KiB
Go
Raw Normal View History

2021-06-21 12:17:00 +00:00
package splitstore
import (
"crypto/sha256"
"encoding/hex"
2021-06-22 07:10:24 +00:00
"fmt"
"os"
"os/exec"
"path/filepath"
"runtime/debug"
"strings"
2021-06-22 07:10:24 +00:00
"sync"
"time"
2021-07-04 06:53:58 +00:00
blocks "github.com/ipfs/go-block-format"
"github.com/ipfs/go-cid"
2022-06-14 15:00:51 +00:00
"go.uber.org/multierr"
"golang.org/x/xerrors"
2021-06-21 12:17:00 +00:00
)
type debugLog struct {
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
2021-06-21 12:17:00 +00:00
}
2021-06-22 07:10:24 +00:00
func openDebugLog(path string) (*debugLog, error) {
basePath := filepath.Join(path, "debug")
err := os.MkdirAll(basePath, 0755)
if err != nil {
return nil, err
2021-06-22 07:10:24 +00:00
}
readLog, err := openDebugLogOp(basePath, "read.log")
2021-06-22 07:10:24 +00:00
if err != nil {
return nil, err
2021-06-22 07:10:24 +00:00
}
writeLog, err := openDebugLogOp(basePath, "write.log")
2021-06-22 07:10:24 +00:00
if err != nil {
_ = readLog.Close()
return nil, err
2021-06-22 07:10:24 +00:00
}
deleteLog, err := openDebugLogOp(basePath, "delete.log")
2021-06-22 07:10:24 +00:00
if err != nil {
_ = readLog.Close()
_ = writeLog.Close()
return nil, err
2021-06-22 07:10:24 +00:00
}
stackLog, err := openDebugLogOp(basePath, "stack.log")
if err != nil {
_ = readLog.Close()
_ = writeLog.Close()
_ = deleteLog.Close()
return nil, xerrors.Errorf("error opening stack log: %w", err)
}
2021-06-22 07:10:24 +00:00
return &debugLog{
readLog: readLog,
writeLog: writeLog,
deleteLog: deleteLog,
stackLog: stackLog,
stackMap: make(map[string]string),
2021-06-22 07:10:24 +00:00
}, nil
}
func (d *debugLog) LogReadMiss(cid cid.Cid) {
2021-06-21 12:17:00 +00:00
if d == nil {
return
}
stack := d.getStack()
err := d.readLog.Log("%s %s %s\n", d.timestamp(), cid, stack)
2021-06-22 07:10:24 +00:00
if err != nil {
log.Warnf("error writing read log: %s", err)
}
2021-06-21 12:17:00 +00:00
}
func (d *debugLog) LogWrite(blk blocks.Block) {
2021-06-21 12:17:00 +00:00
if d == nil {
return
}
var stack string
if enableDebugLogWriteTraces {
stack = " " + d.getStack()
}
err := d.writeLog.Log("%s %s%s\n", d.timestamp(), blk.Cid(), stack)
2021-06-22 07:10:24 +00:00
if err != nil {
log.Warnf("error writing write log: %s", err)
}
2021-06-21 12:17:00 +00:00
}
func (d *debugLog) LogWriteMany(blks []blocks.Block) {
2021-06-21 12:17:00 +00:00
if d == nil {
return
}
var stack string
if enableDebugLogWriteTraces {
stack = " " + d.getStack()
}
2021-06-29 13:29:03 +00:00
now := d.timestamp()
2021-07-04 06:53:58 +00:00
for _, blk := range blks {
err := d.writeLog.Log("%s %s%s\n", now, blk.Cid(), stack)
2021-06-22 07:10:24 +00:00
if err != nil {
log.Warnf("error writing write log: %s", err)
break
}
}
2021-06-21 12:17:00 +00:00
}
func (d *debugLog) LogDelete(cids []cid.Cid) {
2021-06-21 12:17:00 +00:00
if d == nil {
return
}
now := d.timestamp()
for _, c := range cids {
err := d.deleteLog.Log("%s %s\n", now, c)
if err != nil {
log.Warnf("error writing delete log: %s", err)
break
}
2021-06-22 07:10:24 +00:00
}
2021-06-21 12:17:00 +00:00
}
2021-06-22 07:10:24 +00:00
func (d *debugLog) Flush() {
if d == nil {
return
}
2021-06-22 07:10:24 +00:00
// rotate non-empty logs
d.readLog.Rotate()
d.writeLog.Rotate()
d.deleteLog.Rotate()
d.stackLog.Rotate()
}
2021-06-21 12:17:00 +00:00
func (d *debugLog) Close() error {
if d == nil {
return nil
}
2021-06-22 07:10:24 +00:00
err1 := d.readLog.Close()
err2 := d.writeLog.Close()
err3 := d.deleteLog.Close()
err4 := d.stackLog.Close()
return multierr.Combine(err1, err2, err3, err4)
}
func (d *debugLog) getStack() string {
sk := d.getNormalizedStackTrace()
hash := sha256.Sum256([]byte(sk))
key := string(hash[:])
d.stackMx.Lock()
2021-06-29 13:50:54 +00:00
repr, ok := d.stackMap[key]
if !ok {
2021-06-29 13:50:54 +00:00
repr = hex.EncodeToString(hash[:])
d.stackMap[key] = repr
err := d.stackLog.Log("%s\n%s\n", repr, sk)
if err != nil {
2021-06-29 13:50:54 +00:00
log.Warnf("error writing stack trace for %s: %s", repr, err)
}
}
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 {
2021-06-29 13:21:20 +00:00
if len(line) > 0 && line[len(line)-1] == ')' {
idx := strings.LastIndex(line, "(")
2021-06-29 13:18:25 +00:00
if idx < 0 {
continue
}
lines[i] = line[:idx]
}
}
return strings.Join(lines, "\n")
2021-06-21 12:17:00 +00:00
}
2021-06-29 13:29:03 +00:00
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
}
}