From b15e874d00e113813a928ef4769e8a73fd6090a5 Mon Sep 17 00:00:00 2001 From: Luke Shumaker Date: Sat, 24 Dec 2022 23:05:34 -0700 Subject: textui: Add some utilities for human-friendly text --- lib/textui/text.go | 85 +++++++++++++++++++++++++++++++++++++++++++++++++ lib/textui/text_test.go | 39 +++++++++++++++++++++++ 2 files changed, 124 insertions(+) create mode 100644 lib/textui/text.go create mode 100644 lib/textui/text_test.go (limited to 'lib/textui') diff --git a/lib/textui/text.go b/lib/textui/text.go new file mode 100644 index 0000000..f628eab --- /dev/null +++ b/lib/textui/text.go @@ -0,0 +1,85 @@ +// Copyright (C) 2022 Luke Shumaker +// +// SPDX-License-Identifier: GPL-2.0-or-later + +package textui + +import ( + "fmt" + "io" + + "golang.org/x/exp/constraints" + "golang.org/x/text/language" + "golang.org/x/text/message" + "golang.org/x/text/number" + + "git.lukeshu.com/btrfs-progs-ng/lib/fmtutil" +) + +var printer = message.NewPrinter(language.English) + +// Fprintf is like `fmt.Fprintf`, but (1) includes the extensions of +// `golang.org/x/text/message.Printer`, and (2) is useful for marking +// when a print call is part of the UI, rather than something +// internal. +func Fprintf(w io.Writer, key string, a ...any) (n int, err error) { + return printer.Fprintf(w, key, a...) +} + +// Sprintf is like `fmt.Sprintf`, but (1) includes the extensions of +// `golang.org/x/text/message.Printer`, and (2) is useful for marking +// when a sprint call is part of the UI, rather than something +// internal. +func Sprintf(key string, a ...any) string { + return printer.Sprintf(key, a...) +} + +// Humanized wraps a value such that formatting of it can make use of +// the `golang.org/x/text/message.Printer` extensions even when used +// with plain-old `fmt`. +func Humanized(x any) any { + return humanized{val: x} +} + +type humanized struct { + val any +} + +var ( + _ fmt.Formatter = humanized{} + _ fmt.Stringer = humanized{} +) + +// String implements fmt.Formatter. +func (h humanized) Format(f fmt.State, verb rune) { + printer.Fprintf(f, fmtutil.FmtStateString(f, verb), h.val) +} + +// String implements fmt.Stringer. +func (h humanized) String() string { + return fmt.Sprint(h) +} + +// Portion renders a fraction N/D as both a percentage and +// parenthetically as the exact fractional value, rendered with +// human-friendly commas. +// +// For example: +// +// fmt.Sprint(Portion[int]{N: 1, D: 12345}) ⇒ "0% (1/12,345)" +type Portion[T constraints.Integer] struct { + N, D T +} + +var ( + _ fmt.Stringer = Portion[int]{} +) + +// String implements fmt.Stringer. +func (p Portion[T]) String() string { + pct := float64(1) + if p.D > 0 { + pct = float64(p.N) / float64(p.D) + } + return printer.Sprintf("%v (%v/%v)", number.Percent(pct), uint64(p.N), uint64(p.D)) +} diff --git a/lib/textui/text_test.go b/lib/textui/text_test.go new file mode 100644 index 0000000..c4b42f6 --- /dev/null +++ b/lib/textui/text_test.go @@ -0,0 +1,39 @@ +// Copyright (C) 2022 Luke Shumaker +// +// SPDX-License-Identifier: GPL-2.0-or-later + +package textui_test + +import ( + "fmt" + "strings" + "testing" + + "github.com/stretchr/testify/assert" + + "git.lukeshu.com/btrfs-progs-ng/lib/btrfs/btrfsvol" + "git.lukeshu.com/btrfs-progs-ng/lib/textui" +) + +func TestFprintf(t *testing.T) { + var out strings.Builder + textui.Fprintf(&out, "%d", 12345) + assert.Equal(t, "12,345", out.String()) +} + +func TestHumanized(t *testing.T) { + assert.Equal(t, "12,345", fmt.Sprint(textui.Humanized(12345))) + assert.Equal(t, "12,345 ", fmt.Sprintf("%-8d", textui.Humanized(12345))) + + laddr := btrfsvol.LogicalAddr(345243543) + assert.Equal(t, "0x000000001493ff97", fmt.Sprintf("%v", textui.Humanized(laddr))) + assert.Equal(t, "345243543", fmt.Sprintf("%d", textui.Humanized(laddr))) + assert.Equal(t, "345,243,543", fmt.Sprintf("%d", textui.Humanized(uint64(laddr)))) +} + +func TestPortion(t *testing.T) { + assert.Equal(t, "100% (0/0)", fmt.Sprint(textui.Portion[int]{})) + assert.Equal(t, "0% (1/12,345)", fmt.Sprint(textui.Portion[int]{N: 1, D: 12345})) + assert.Equal(t, "100% (0/0)", fmt.Sprint(textui.Portion[btrfsvol.PhysicalAddr]{})) + assert.Equal(t, "0% (1/12,345)", fmt.Sprint(textui.Portion[btrfsvol.PhysicalAddr]{N: 1, D: 12345})) +} -- cgit v1.2.3-2-g168b From 31341857abc73334852d3b888f4fb558d8ed3c61 Mon Sep 17 00:00:00 2001 From: Luke Shumaker Date: Sun, 25 Dec 2022 14:03:02 -0700 Subject: Factor logger code from main.go in to textui --- lib/textui/log.go | 33 +++++++++++++++++++++++++++++++++ 1 file changed, 33 insertions(+) create mode 100644 lib/textui/log.go (limited to 'lib/textui') diff --git a/lib/textui/log.go b/lib/textui/log.go new file mode 100644 index 0000000..cee51db --- /dev/null +++ b/lib/textui/log.go @@ -0,0 +1,33 @@ +// Copyright (C) 2022 Luke Shumaker +// +// SPDX-License-Identifier: GPL-2.0-or-later + +package textui + +import ( + "github.com/datawire/dlib/dlog" + "github.com/sirupsen/logrus" + "github.com/spf13/pflag" +) + +type LogLevelFlag struct { + logrus.Level +} + +var _ pflag.Value = (*LogLevelFlag)(nil) + +// Type implements pflag.Value. +func (lvl *LogLevelFlag) Type() string { return "loglevel" } + +// Type implements pflag.Value. +func (lvl *LogLevelFlag) Set(str string) error { + var err error + lvl.Level, err = logrus.ParseLevel(str) + return err +} + +func NewLogger(lvl logrus.Level) dlog.Logger { + logger := logrus.New() + logger.SetLevel(lvl) + return dlog.WrapLogrus(logger) +} -- cgit v1.2.3-2-g168b From 29ad8ec24e07888953c14fb5435d2e8e2023931b Mon Sep 17 00:00:00 2001 From: Luke Shumaker Date: Sun, 25 Dec 2022 22:47:51 -0700 Subject: textui: Implement a custom dlog backend that uses x/text/message --- lib/textui/log.go | 282 +++++++++++++++++++++++++++++++++++++++++++++++-- lib/textui/log_test.go | 64 +++++++++++ 2 files changed, 336 insertions(+), 10 deletions(-) create mode 100644 lib/textui/log_test.go (limited to 'lib/textui') diff --git a/lib/textui/log.go b/lib/textui/log.go index cee51db..ca8c201 100644 --- a/lib/textui/log.go +++ b/lib/textui/log.go @@ -1,17 +1,33 @@ +// Copyright (C) 2019-2022 Ambassador Labs // Copyright (C) 2022 Luke Shumaker // -// SPDX-License-Identifier: GPL-2.0-or-later +// SPDX-License-Identifier: Apache-2.0 +// +// Contains code based on: +// https://github.com/datawire/dlib/blob/b09ab2e017e16d261f05fff5b3b860d645e774d4/dlog/logger_logrus.go +// https://github.com/datawire/dlib/blob/b09ab2e017e16d261f05fff5b3b860d645e774d4/dlog/logger_testing.go +// https://github.com/telepresenceio/telepresence/blob/ece94a40b00a90722af36b12e40f91cbecc0550c/pkg/log/formatter.go package textui import ( + "bytes" + "fmt" + "io" + "log" + "path/filepath" + "runtime" + "sort" + "strings" + "sync" + "time" + "github.com/datawire/dlib/dlog" - "github.com/sirupsen/logrus" "github.com/spf13/pflag" ) type LogLevelFlag struct { - logrus.Level + Level dlog.LogLevel } var _ pflag.Value = (*LogLevelFlag)(nil) @@ -21,13 +37,259 @@ func (lvl *LogLevelFlag) Type() string { return "loglevel" } // Type implements pflag.Value. func (lvl *LogLevelFlag) Set(str string) error { - var err error - lvl.Level, err = logrus.ParseLevel(str) - return err + switch strings.ToLower(str) { + case "error": + lvl.Level = dlog.LogLevelError + case "warn", "warning": + lvl.Level = dlog.LogLevelWarn + case "info": + lvl.Level = dlog.LogLevelInfo + case "debug": + lvl.Level = dlog.LogLevelDebug + case "trace": + lvl.Level = dlog.LogLevelTrace + default: + return fmt.Errorf("invalid log level: %q", str) + } + return nil +} + +// Type implements pflag.Value. +func (lvl *LogLevelFlag) String() string { + switch lvl.Level { + case dlog.LogLevelError: + return "error" + case dlog.LogLevelWarn: + return "warn" + case dlog.LogLevelInfo: + return "info" + case dlog.LogLevelDebug: + return "debug" + case dlog.LogLevelTrace: + return "trace" + default: + panic(fmt.Errorf("invalid log level: %#v", lvl.Level)) + } +} + +type logger struct { + parent *logger + out io.Writer + lvl dlog.LogLevel + + // only valid if parent is non-nil + fieldKey string + fieldVal any +} + +var _ dlog.OptimizedLogger = (*logger)(nil) + +func NewLogger(out io.Writer, lvl dlog.LogLevel) dlog.Logger { + return &logger{ + out: out, + lvl: lvl, + } +} + +// Helper implements dlog.Logger. +func (l *logger) Helper() {} + +// WithField implements dlog.Logger. +func (l *logger) WithField(key string, value any) dlog.Logger { + return &logger{ + parent: l, + out: l.out, + lvl: l.lvl, + + fieldKey: key, + fieldVal: value, + } +} + +type logWriter struct { + log *logger + lvl dlog.LogLevel +} + +// Write implements io.Writer. +func (lw logWriter) Write(data []byte) (int, error) { + lw.log.log(lw.lvl, func(w io.Writer) { + _, _ = w.Write(data) + }) + return len(data), nil +} + +// StdLogger implements dlog.Logger. +func (l *logger) StdLogger(lvl dlog.LogLevel) *log.Logger { + return log.New(logWriter{log: l, lvl: lvl}, "", 0) +} + +// Log implements dlog.Logger. +func (l *logger) Log(lvl dlog.LogLevel, msg string) { + panic("should not happen: optimized log methods should be used instead") +} + +// UnformattedLog implements dlog.OptimizedLogger. +func (l *logger) UnformattedLog(lvl dlog.LogLevel, args ...any) { + l.log(lvl, func(w io.Writer) { + printer.Fprint(w, args...) + }) +} + +// UnformattedLogln implements dlog.OptimizedLogger. +func (l *logger) UnformattedLogln(lvl dlog.LogLevel, args ...any) { + l.log(lvl, func(w io.Writer) { + printer.Fprintln(w, args...) + }) +} + +// UnformattedLogf implements dlog.OptimizedLogger. +func (l *logger) UnformattedLogf(lvl dlog.LogLevel, format string, args ...any) { + l.log(lvl, func(w io.Writer) { + printer.Fprintf(w, format, args...) + }) +} + +var ( + logBuf bytes.Buffer + logMu sync.Mutex + thisModDir string +) + +func init() { + _, file, _, _ := runtime.Caller(0) + thisModDir = filepath.Dir(filepath.Dir(filepath.Dir(file))) +} + +func (l *logger) log(lvl dlog.LogLevel, writeMsg func(io.Writer)) { + // boilerplate ///////////////////////////////////////////////////////// + if lvl > l.lvl { + return + } + // This is optimized for mostly-single-threaded usage. If I cared more + // about multi-threaded performance, I'd trade in some + // memory-use/allocations and (1) instead of using a static `logBuf`, + // I'd have a `logBufPool` `sync.Pool`, and (2) have the the final call + // to `l.out.Write()` be the only thing protected by `logMu`. + logMu.Lock() + defer logMu.Unlock() + defer logBuf.Reset() + + // time //////////////////////////////////////////////////////////////// + now := time.Now() + const timeFmt = "2006-01-02 15:04:05.0000" + logBuf.WriteString(timeFmt) + now.AppendFormat(logBuf.Bytes()[:0], timeFmt) + + // level /////////////////////////////////////////////////////////////// + switch lvl { + case dlog.LogLevelError: + logBuf.WriteString(" ERR") + case dlog.LogLevelWarn: + logBuf.WriteString(" WRN") + case dlog.LogLevelInfo: + logBuf.WriteString(" INF") + case dlog.LogLevelDebug: + logBuf.WriteString(" DBG") + case dlog.LogLevelTrace: + logBuf.WriteString(" TRC") + } + + // fields (early) ////////////////////////////////////////////////////// + fields := make(map[string]any) + var fieldKeys []string + for f := l; f.parent != nil; f = f.parent { + if _, exists := fields[f.fieldKey]; exists { + continue + } + fields[f.fieldKey] = f.fieldVal + fieldKeys = append(fieldKeys, f.fieldKey) + } + sort.Slice(fieldKeys, func(i, j int) bool { + iOrd := fieldOrd(fieldKeys[i]) + jOrd := fieldOrd(fieldKeys[j]) + if iOrd != jOrd { + return iOrd < jOrd + } + return fieldKeys[i] < fieldKeys[j] + }) + nextField := len(fieldKeys) + for i, fieldKey := range fieldKeys { + if fieldOrd(fieldKey) >= 0 { + nextField = i + break + } + printer.Fprintf(&logBuf, " %s=%v", fieldName(fieldKey), fields[fieldKey]) + } + + // message ///////////////////////////////////////////////////////////// + logBuf.WriteString(" : ") + writeMsg(&logBuf) + + // fields (late) /////////////////////////////////////////////////////// + if nextField < len(fieldKeys) { + logBuf.WriteString(" :") + } + for _, fieldKey := range fieldKeys[nextField:] { + printer.Fprintf(&logBuf, " %s=%v", fieldName(fieldKey), fields[fieldKey]) + } + + // caller ////////////////////////////////////////////////////////////// + const ( + thisModule = "git.lukeshu.com/btrfs-progs-ng" + thisPackage = "git.lukeshu.com/btrfs-progs-ng/lib/textui" + maximumCallerDepth int = 25 + minimumCallerDepth int = 3 // runtime.Callers + .log + .Log + ) + var pcs [maximumCallerDepth]uintptr + depth := runtime.Callers(minimumCallerDepth, pcs[:]) + frames := runtime.CallersFrames(pcs[:depth]) + for f, again := frames.Next(); again; f, again = frames.Next() { + if !strings.HasPrefix(f.Function, thisModule+"/") { + continue + } + if strings.HasPrefix(f.Function, thisPackage+".") { + continue + } + if nextField == len(fieldKeys) { + logBuf.WriteString(" :") + } + file := f.File[strings.LastIndex(f.File, thisModDir+"/")+len(thisModDir+"/"):] + fmt.Fprintf(&logBuf, " (from %s:%d)", file, f.Line) + break + } + + // boilerplate ///////////////////////////////////////////////////////// + logBuf.WriteByte('\n') + _, _ = l.out.Write(logBuf.Bytes()) +} + +// fieldOrd returns the sort-position for a given log-field-key. Lower return +// values should be positioned on the left when logging, and higher values +// should be positioned on the right; values <0 should be on the left of the log +// message, while values ≥0 should be on the right of the log message. +func fieldOrd(key string) int { + switch key { + case "THREAD": // dgroup + return -7 + case "dexec.pid": + return -6 + case "dexec.stream": + return -5 + case "dexec.data": + return -4 + case "dexec.err": + return -3 + default: + return 1 + } } -func NewLogger(lvl logrus.Level) dlog.Logger { - logger := logrus.New() - logger.SetLevel(lvl) - return dlog.WrapLogrus(logger) +func fieldName(key string) string { + switch key { + case "THREAD": + return "thread" + default: + return key + } } diff --git a/lib/textui/log_test.go b/lib/textui/log_test.go new file mode 100644 index 0000000..08eb38c --- /dev/null +++ b/lib/textui/log_test.go @@ -0,0 +1,64 @@ +// Copyright (C) 2022 Luke Shumaker +// +// SPDX-License-Identifier: GPL-2.0-or-later + +package textui_test + +import ( + "context" + "strings" + "testing" + + "github.com/datawire/dlib/dlog" + "github.com/stretchr/testify/assert" + + "git.lukeshu.com/btrfs-progs-ng/lib/textui" +) + +func logLineRegexp(inner string) string { + return `[0-9]{4}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}\.[0-9]{4} ` + inner + ` \(from lib/textui/log_test\.go:[0-9]+\)\n` +} + +func TestLogFormat(t *testing.T) { + var out strings.Builder + ctx := dlog.WithLogger(context.Background(), textui.NewLogger(&out, dlog.LogLevelTrace)) + dlog.Debugf(ctx, "foo %d", 12345) + assert.Regexp(t, + `^`+logLineRegexp(`DBG : foo 12,345 :`)+`$`, + out.String()) +} + +func TestLogLevel(t *testing.T) { + var out strings.Builder + ctx := dlog.WithLogger(context.Background(), textui.NewLogger(&out, dlog.LogLevelInfo)) + dlog.Error(ctx, "Error") + dlog.Warn(ctx, "Warn") + dlog.Info(ctx, "Info") + dlog.Debug(ctx, "Debug") + dlog.Trace(ctx, "Trace") + dlog.Trace(ctx, "Trace") + dlog.Debug(ctx, "Debug") + dlog.Info(ctx, "Info") + dlog.Warn(ctx, "Warn") + dlog.Error(ctx, "Error") + assert.Regexp(t, + `^`+ + logLineRegexp(`ERR : Error :`)+ + logLineRegexp(`WRN : Warn :`)+ + logLineRegexp(`INF : Info :`)+ + logLineRegexp(`INF : Info :`)+ + logLineRegexp(`WRN : Warn :`)+ + logLineRegexp(`ERR : Error :`)+ + `$`, + out.String()) +} + +func TestLogField(t *testing.T) { + var out strings.Builder + ctx := dlog.WithLogger(context.Background(), textui.NewLogger(&out, dlog.LogLevelInfo)) + ctx = dlog.WithField(ctx, "foo", 12345) + dlog.Info(ctx, "msg") + assert.Regexp(t, + `^`+logLineRegexp(`INF : msg : foo=12,345`)+`$`, + out.String()) +} -- cgit v1.2.3-2-g168b From 26a23c51f9b3e22ef3e68d0d174d118a78dd4172 Mon Sep 17 00:00:00 2001 From: Luke Shumaker Date: Sun, 25 Dec 2022 23:46:53 -0700 Subject: tree-wide, except rebuildnodes: Fuss with logging to take advantage of textui --- lib/textui/log.go | 17 ++++++++++++++++- 1 file changed, 16 insertions(+), 1 deletion(-) (limited to 'lib/textui') diff --git a/lib/textui/log.go b/lib/textui/log.go index ca8c201..4421074 100644 --- a/lib/textui/log.go +++ b/lib/textui/log.go @@ -280,6 +280,14 @@ func fieldOrd(key string) int { return -4 case "dexec.err": return -3 + + case "btrfsinspect.scandevices.dev": + return -1 + case "btrfsinspect.rebuild-mappings.step": + return -2 + case "btrfsinspect.rebuild-mappings.substep": + return -1 + default: return 1 } @@ -290,6 +298,13 @@ func fieldName(key string) string { case "THREAD": return "thread" default: - return key + switch { + case strings.HasPrefix(key, "btrfsinspect.scandevices."): + return strings.TrimPrefix(key, "btrfsinspect.scandevices.") + case strings.HasPrefix(key, "btrfsinspect.rebuild-mappings."): + return strings.TrimPrefix(key, "btrfsinspect.rebuild-mappings.") + default: + return key + } } } -- cgit v1.2.3-2-g168b From d5737a0e71b17a97b82ae68e49acc41a08fcc0ad Mon Sep 17 00:00:00 2001 From: Luke Shumaker Date: Mon, 26 Dec 2022 22:02:13 -0700 Subject: cmd/btrfs-rec: Add a utility function for reading JSON files with progress --- lib/textui/log.go | 4 ++++ 1 file changed, 4 insertions(+) (limited to 'lib/textui') diff --git a/lib/textui/log.go b/lib/textui/log.go index 4421074..e94a24f 100644 --- a/lib/textui/log.go +++ b/lib/textui/log.go @@ -288,6 +288,8 @@ func fieldOrd(key string) int { case "btrfsinspect.rebuild-mappings.substep": return -1 + case "btrfs.read-json-file": + return -1 default: return 1 } @@ -303,6 +305,8 @@ func fieldName(key string) string { return strings.TrimPrefix(key, "btrfsinspect.scandevices.") case strings.HasPrefix(key, "btrfsinspect.rebuild-mappings."): return strings.TrimPrefix(key, "btrfsinspect.rebuild-mappings.") + case strings.HasPrefix(key, "btrfs."): + return strings.TrimPrefix(key, "btrfs.") default: return key } -- cgit v1.2.3-2-g168b From 6e8e2960c5412685c1ac87c20b4d34d2caf90640 Mon Sep 17 00:00:00 2001 From: Luke Shumaker Date: Mon, 26 Dec 2022 16:32:15 -0700 Subject: rebuildnodes: Fuss with logging to take advantage of textui --- lib/textui/log.go | 124 +++++++++++++++++++++++++++++++++++++++++++++--------- 1 file changed, 104 insertions(+), 20 deletions(-) (limited to 'lib/textui') diff --git a/lib/textui/log.go b/lib/textui/log.go index e94a24f..5ddc7a8 100644 --- a/lib/textui/log.go +++ b/lib/textui/log.go @@ -18,9 +18,11 @@ import ( "path/filepath" "runtime" "sort" + "strconv" "strings" "sync" "time" + "unicode" "github.com/datawire/dlib/dlog" "github.com/spf13/pflag" @@ -219,7 +221,7 @@ func (l *logger) log(lvl dlog.LogLevel, writeMsg func(io.Writer)) { nextField = i break } - printer.Fprintf(&logBuf, " %s=%v", fieldName(fieldKey), fields[fieldKey]) + writeField(&logBuf, fieldKey, fields[fieldKey]) } // message ///////////////////////////////////////////////////////////// @@ -231,7 +233,7 @@ func (l *logger) log(lvl dlog.LogLevel, writeMsg func(io.Writer)) { logBuf.WriteString(" :") } for _, fieldKey := range fieldKeys[nextField:] { - printer.Fprintf(&logBuf, " %s=%v", fieldName(fieldKey), fields[fieldKey]) + writeField(&logBuf, fieldKey, fields[fieldKey]) } // caller ////////////////////////////////////////////////////////////// @@ -270,24 +272,65 @@ func (l *logger) log(lvl dlog.LogLevel, writeMsg func(io.Writer)) { // message, while values ≥0 should be on the right of the log message. func fieldOrd(key string) int { switch key { + // dlib //////////////////////////////////////////////////////////////// case "THREAD": // dgroup - return -7 + return -99 case "dexec.pid": - return -6 + return -98 case "dexec.stream": - return -5 + return -97 case "dexec.data": - return -4 + return -96 case "dexec.err": - return -3 + return -95 + // btrfsinspect scandevices //////////////////////////////////////////// case "btrfsinspect.scandevices.dev": return -1 + + // btrfsinspect rebuild-mappings /////////////////////////////////////// case "btrfsinspect.rebuild-mappings.step": return -2 case "btrfsinspect.rebuild-mappings.substep": return -1 + // btrfsinspect rebuild-nodes ////////////////////////////////////////// + case "btrfsinspect.rebuild-nodes.step": + return -50 + // step=read-fs-data + case "btrfsinspect.rebuild-nodes.read.substep": + return -1 + // step=rebuild + case "btrfsinspect.rebuild-nodes.rebuild.pass": + return -49 + case "btrfsinspect.rebuild-nodes.rebuild.substep": + return -48 + case "btrfsinspect.rebuild-nodes.rebuild.substep.progress": + return -47 + // step=rebuild, substep=collect-items (1/3) + // step=rebuild, substep=process-items (2/3) + case "btrfsinspect.rebuild-nodes.rebuild.process.item": + return -25 + // step=rebuild, substep=apply-augments (3/3) + case "btrfsinspect.rebuild-nodes.rebuild.augment.tree": + return -25 + // step=rebuild (any substep) + case "btrfsinspect.rebuild-nodes.rebuild.want.key": + return -7 + case "btrfsinspect.rebuild-nodes.rebuild.want.reason": + return -6 + case "btrfsinspect.rebuild-nodes.rebuild.add-tree": + return -5 + case "btrfsinspect.rebuild-nodes.rebuild.add-tree.substep": + return -4 + case "btrfsinspect.rebuild-nodes.rebuild.add-tree.want.key": + return -3 + case "btrfsinspect.rebuild-nodes.rebuild.add-tree.want.reason": + return -2 + case "btrfsinspect.rebuild-nodes.rebuild.add-root": + return -1 + + // other /////////////////////////////////////////////////////////////// case "btrfs.read-json-file": return -1 default: @@ -295,20 +338,61 @@ func fieldOrd(key string) int { } } -func fieldName(key string) string { - switch key { - case "THREAD": - return "thread" - default: - switch { - case strings.HasPrefix(key, "btrfsinspect.scandevices."): - return strings.TrimPrefix(key, "btrfsinspect.scandevices.") - case strings.HasPrefix(key, "btrfsinspect.rebuild-mappings."): - return strings.TrimPrefix(key, "btrfsinspect.rebuild-mappings.") - case strings.HasPrefix(key, "btrfs."): - return strings.TrimPrefix(key, "btrfs.") +func writeField(w io.Writer, key string, val any) { + valStr := printer.Sprint(val) + needsQuote := false + if strings.HasPrefix(valStr, `"`) { + needsQuote = true + } else { + for _, r := range valStr { + if !(unicode.IsPrint(r) && r != ' ') { + needsQuote = true + break + } + } + } + if needsQuote { + valStr = strconv.Quote(valStr) + } + + name := key + + switch { + case name == "THREAD": + name = "thread" + switch valStr { + case "", "/main": + return default: - return key + if strings.HasPrefix(valStr, "/main/") { + valStr = strings.TrimPrefix(valStr, "/main") + } } + case strings.HasSuffix(name, ".pass"): + fmt.Fprintf(w, "/pass-%s", valStr) + return + case strings.HasSuffix(name, ".substep") && name != "btrfsinspect.rebuild-nodes.rebuild.add-tree.substep": + fmt.Fprintf(w, "/%s", valStr) + return + case strings.HasPrefix(name, "btrfsinspect."): + name = strings.TrimPrefix(name, "btrfsinspect.") + switch { + case strings.HasPrefix(name, "scandevices."): + name = strings.TrimPrefix(name, "scandevices.") + case strings.HasPrefix(name, "rebuild-mappings."): + name = strings.TrimPrefix(name, "rebuild-mappings.") + case strings.HasPrefix(name, "rebuild-nodes."): + name = strings.TrimPrefix(name, "rebuild-nodes.") + switch { + case strings.HasPrefix(name, "read."): + name = strings.TrimPrefix(name, "read.") + case strings.HasPrefix(name, "rebuild."): + name = strings.TrimPrefix(name, "rebuild.") + } + } + case strings.HasPrefix(name, "btrfs."): + name = strings.TrimPrefix(name, "btrfs.") } + + fmt.Fprintf(w, " %s=%s", name, valStr) } -- cgit v1.2.3-2-g168b From 3d0937e9ab148c074922b0d46ed33bdbcbef85b5 Mon Sep 17 00:00:00 2001 From: Luke Shumaker Date: Wed, 28 Dec 2022 18:14:14 -0700 Subject: cmd/btrfs-rec: Have all logging include live memory statistics --- lib/textui/log_memstats.go | 132 +++++++++++++++++++++++++++++++++++++++++++++ lib/textui/text.go | 119 ++++++++++++++++++++++++++++++++++++++++ 2 files changed, 251 insertions(+) create mode 100644 lib/textui/log_memstats.go (limited to 'lib/textui') diff --git a/lib/textui/log_memstats.go b/lib/textui/log_memstats.go new file mode 100644 index 0000000..39733c6 --- /dev/null +++ b/lib/textui/log_memstats.go @@ -0,0 +1,132 @@ +// Copyright (C) 2022 Luke Shumaker +// +// SPDX-License-Identifier: GPL-2.0-or-later + +package textui + +import ( + "fmt" + "runtime" + "sync" + "time" +) + +type LiveMemUse struct { + mu sync.Mutex + stats runtime.MemStats + last time.Time +} + +var _ fmt.Stringer = (*LiveMemUse)(nil) + +const liveMemUseUpdateInterval = 1 * time.Second + +func (o *LiveMemUse) String() string { + o.mu.Lock() + + // runtime.ReadMemStats() calls stopTheWorld(), so we want to + // rate-limit how often we call it. + if now := time.Now(); now.Sub(o.last) > liveMemUseUpdateInterval { + runtime.ReadMemStats(&o.stats) + o.last = now + } + + // runtime.MemStats only knows about memory managed by the Go runtime; + // even for a pure Go program, there's also + // + // - memory mapped to the executable itself + // - vDSO and friends + // + // But those are pretty small, just a few MiB. + // + // OK, so: memory managed by the Go runtime. runtime.MemStats is pretty + // obtuse, I think it was designed more for "debugging the Go runtime" + // than "monitoring the behavior of a Go program". From the Go + // runtime's perspective, regions of the virtual address space are in + // one of 4 states (see `runtime/mem.go`): + // + // - None : not mapped + // + // - Reserved : mapped, but without r/w permissions (PROT_NONE); so + // this region isn't actually backed by anything + // + // - Prepared : mapped, but allowed to be collected by the OS + // (MADV_FREE, or MADV_DONTNEED on systems without MADV_FREE); so + // this region may or may not actually be backed by anything. + // + // - Ready : mapped, ready to be used + // + // Normal tools count Reserved+Prepared+Ready toward the VSS (which is a + // little silly, when inspecting /proc/{pid}/maps to calculate the VSS, + // IMO they should exclude maps without r/w permissions, which would + // exclude Reserved), but we all know that VSS numbers are over + // inflated. And RSS only useful if we fit in RAM and don't spill to + // swap (this is being written for btrfs-rec, which is quite likely to + // consume all RAM on a laptop). Useful numbers are Ready and Prepared; + // as I said above, outside tools reporting Ready+Prepared would be easy + // and useful, but none do; but I don't think outside tools have a way + // to distinguish between Ready and Prepared (unless you can detect + // MADV_FREE/MADV_DONTNEED in /proc/{pid}/smaps?). + // + // Of the 3 mapped states, here's how we get them from runtime: + // + // - Reserved : AFAICT, you can't :( + // + // - Prepared : `runtime.MemStats.HeapReleased` + // + // - Ready : `runtime.MemStats.Sys - runtime.MemStats.HeapReleased` + // (that is, runtime.MemStats.Sys is Prepared+Ready) + // + // It's a bummer that we can't get Reserved from runtime, but as I've + // said, it's not super useful; it's only use would really be + // cross-referencing runtime's numbers against the VSS. + // + // The godocs for runtime.MemStats.Sys say "It's likely that not all of + // the virtual address space is backed by physical memory at any given + // moment, though in general it all was at some point." That's both + // confusing and a lie. It's confusing because it doesn't give you + // hooks to find out more; it could have said that this is + // Ready+Prepared and that Prepared is the portion of the space that + // might not be backed by physical memory, but instead it wants you to + // throw your hands up and say "this is too weird for me to understand". + // It's a lie because "in general it all was at some point" implies that + // all Prepared memory was previously Ready, which is false; it can go + // None->Reserved->Prepared (but it only does that Reserved->Prepared + // transition if it thinks it will need to transition it to Ready very + // soon, so maybe the doc author though that was negligible?). + // + // Now, those are still pretty opaque numbers; most of runtime.MemStats + // goes toward accounting for what's going on inside of Ready space. + // + // For our purposes, we don't care too much about specifics of how Ready + // space is being used; just how much is "actually storing data", vs + // "overhead from heap-fragmentation", vs "idle". + + var ( + // We're going to add up all of the `o.stats.{thing}Sys` + // variables and check that against `o.stats.Sys`, in order to + // make sure that we're not missing any {thing} when adding up + // `inuse`. + calcSys = o.stats.HeapSys + o.stats.StackSys + o.stats.MSpanSys + o.stats.MCacheSys + o.stats.BuckHashSys + o.stats.GCSys + o.stats.OtherSys + inuse = o.stats.HeapInuse + o.stats.StackInuse + o.stats.MSpanInuse + o.stats.MCacheInuse + o.stats.BuckHashSys + o.stats.GCSys + o.stats.OtherSys + ) + if calcSys != o.stats.Sys { + panic("should not happen") + } + prepared := o.stats.HeapReleased + ready := o.stats.Sys - prepared + + readyFragOverhead := o.stats.HeapInuse - o.stats.HeapAlloc + readyData := inuse - readyFragOverhead + readyIdle := ready - inuse + + o.mu.Unlock() + + return Sprintf("Ready+Prepared=%.1f (Ready=%.1f (data:%.1f + fragOverhead:%.1f + idle:%.1f) ; Prepared=%.1f)", + IEC(ready+prepared, "B"), + IEC(ready, "B"), + IEC(readyData, "B"), + IEC(readyFragOverhead, "B"), + IEC(readyIdle, "B"), + IEC(prepared, "B")) +} diff --git a/lib/textui/text.go b/lib/textui/text.go index f628eab..d6a80b3 100644 --- a/lib/textui/text.go +++ b/lib/textui/text.go @@ -7,6 +7,7 @@ package textui import ( "fmt" "io" + "math" "golang.org/x/exp/constraints" "golang.org/x/text/language" @@ -83,3 +84,121 @@ func (p Portion[T]) String() string { } return printer.Sprintf("%v (%v/%v)", number.Percent(pct), uint64(p.N), uint64(p.D)) } + +type metric[T constraints.Integer | constraints.Float] struct { + Val T + Unit string +} + +var ( + _ fmt.Formatter = metric[int]{} + _ fmt.Stringer = metric[int]{} +) + +func Metric[T constraints.Integer | constraints.Float](x T, unit string) metric[T] { + return metric[T]{ + Val: x, + Unit: unit, + } +} + +var metricSmallPrefixes = []string{ + "m", + "μ", + "n", + "p", + "f", + "a", + "z", + "y", + "r", + "q", +} + +var metricBigPrefixes = []string{ + "k", + "M", + "G", + "T", + "P", + "E", + "Z", + "Y", + "R", + "Q", +} + +// String implements fmt.Formatter. +func (v metric[T]) Format(f fmt.State, verb rune) { + var prefix string + y := math.Abs(float64(v.Val)) + if y < 1 { + for i := 0; y < 1 && i <= len(metricSmallPrefixes); i++ { + y *= 1000 + prefix = metricSmallPrefixes[i] + } + } else { + for i := 0; y > 1000 && i <= len(metricBigPrefixes); i++ { + y /= 1000 + prefix = metricBigPrefixes[i] + } + } + if v.Val < 0 { + y = -y + } + printer.Fprintf(f, fmtutil.FmtStateString(f, verb)+"%s%s", + y, prefix, v.Unit) +} + +// String implements fmt.Stringer. +func (v metric[T]) String() string { + return fmt.Sprint(v) +} + +type iec[T constraints.Integer | constraints.Float] struct { + Val T + Unit string +} + +var ( + _ fmt.Formatter = iec[int]{} + _ fmt.Stringer = iec[int]{} +) + +func IEC[T constraints.Integer | constraints.Float](x T, unit string) iec[T] { + return iec[T]{ + Val: x, + Unit: unit, + } +} + +var iecPrefixes = []string{ + "Ki", + "Mi", + "Gi", + "Ti", + "Pi", + "Ei", + "Zi", + "Yi", +} + +// String implements fmt.Formatter. +func (v iec[T]) Format(f fmt.State, verb rune) { + var prefix string + y := math.Abs(float64(v.Val)) + for i := 0; y > 1024 && i <= len(iecPrefixes); i++ { + y /= 1024 + prefix = iecPrefixes[i] + } + if v.Val < 0 { + y = -y + } + printer.Fprintf(f, fmtutil.FmtStateString(f, verb)+"%s%s", + number.Decimal(y), prefix, v.Unit) +} + +// String implements fmt.Stringer. +func (v iec[T]) String() string { + return fmt.Sprint(v) +} -- cgit v1.2.3-2-g168b