From 3997483ce717e87f10ffbdccf0fbf63c6f5d3d14 Mon Sep 17 00:00:00 2001 From: Klaus Post Date: Wed, 5 Jun 2024 00:50:20 -0700 Subject: [PATCH] Add sizes to mc admin trace (#4949) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ``` Regular trace: 2024-06-03T14:18:37.303 [STORAGE] storage.ReadXL 127.0.0.1:9001 e:\data\distxl\s1\d3 warp-benchmark-bucket pz9WSPPj/4.TnpU8KEot9t4zl66.rnd 538.3µs 1003 B With -v: 127.0.0.1:9001 [STORAGE storage.ReadXL] [2024-06-03T14:14:51.680] e:\data\distxl\s1\d3 warp-benchmark-bucket yvhiOPYp/117.hjDOOH6KmAhtC0Ty.rnd total-errs-availability=0 total-errs-timeout=0 0s 1003 B With -stats Duration: 21s ∙∙● Call Count RPM Avg Time Min Time Max Time Avg TTFB Max TTFB Avg Size Errors storage.ReadXL 15808 (67.2%) 44344.8 429µs 0s 69.9984ms 0s 0s 1.2 KiB 0 storage.Delete 3088 (13.1%) 8662.5 2.056ms 9.7075ms 305.0662ms 0s 0s - 3 http stats: Duration: 14s ∙∙● Call Count RPM Avg Time Min Time Max Time Avg TTFB Max TTFB Avg Size Errors s3.GetObject 4532 (44.1%) 19502.8 1.121ms 267.5µs 67.9369ms 1.098ms 67.9369ms ↓77 B ↑1000 B 0 s3.HeadObject 3028 (29.4%) 13030.6 1.031ms 506.8µs 62.9893ms 0s 0s ↓77 B 0 s3.PutObject 1711 (16.6%) 7363.1 21.109ms 2.5496ms 181.8214ms 9µs 10.6771ms ↓1.3 KiB ↑0 B 0 s3.DeleteObject 1008 (9.8%) 4337.8 56.204ms 1.5859ms 411.1034ms 1.185ms 175.1619ms ↓77 B ↑4 B 0 s3.DeleteMultipleObjects 1 (0.0%) 4.3 316.358ms 316.3584ms 316.3584ms 315.306ms 315.3055ms ↓23 KiB ↑24 KiB 0 ``` Backwards compatible, but will start displaying non-zero after: https://github.com/minio/minio/pull/19851 and https://github.com/minio/minio/pull/19864 --- cmd/admin-trace.go | 125 +++++++++++++++++++++++++++++++++------------ cmd/main.go | 2 +- go.mod | 2 +- go.sum | 4 +- 4 files changed, 95 insertions(+), 38 deletions(-) diff --git a/cmd/admin-trace.go b/cmd/admin-trace.go index 1849157418..e3f823f3ec 100644 --- a/cmd/admin-trace.go +++ b/cmd/admin-trace.go @@ -24,6 +24,7 @@ import ( "hash/fnv" "net/http" "net/url" + "os" "path" "sort" "strconv" @@ -41,7 +42,9 @@ import ( "github.com/minio/madmin-go/v3" "github.com/minio/mc/pkg/probe" "github.com/minio/pkg/v3/console" + "github.com/muesli/reflow/truncate" "github.com/olekukonko/tablewriter" + "golang.org/x/term" ) var adminTraceFlags = []cli.Flag{ @@ -582,6 +585,7 @@ type shortTraceMsg struct { StatusCode int `json:"statusCode"` StatusMsg string `json:"statusMsg"` Type string `json:"type"` + Size int64 `json:"size,omitempty"` Error string `json:"error"` Extra map[string]string `json:"extra"` trcType madmin.TraceType @@ -650,6 +654,7 @@ func shortTrace(ti madmin.ServiceTraceInfo) shortTraceMsg { s.Duration = t.Duration s.StatusMsg = t.Message s.Extra = t.Custom + s.Size = t.Bytes switch t.TraceType { case madmin.TraceS3, madmin.TraceInternal: @@ -703,10 +708,15 @@ func (s shortTraceMsg) String() string { console.Colorize("ErrStatus", s.Error), console.Colorize("HeaderValue", s.Duration)) } else { - fmt.Fprintf(b, "[%s] %s %s %s %2s", console.Colorize("RespStatus", strings.ToUpper(s.trcType.String())), console.Colorize("FuncName", s.FuncName), + sz := "" + if s.Size != 0 { + sz = fmt.Sprintf(" %s", humanize.IBytes(uint64(s.Size))) + } + fmt.Fprintf(b, "[%s] %s %s %s %2s%s", console.Colorize("RespStatus", strings.ToUpper(s.trcType.String())), console.Colorize("FuncName", s.FuncName), hostStr, s.Path, - console.Colorize("HeaderValue", s.Duration)) + console.Colorize("HeaderValue", s.Duration), + sz) } return b.String() } @@ -839,10 +849,14 @@ func (t traceMessage) String() string { fmt.Fprintf(b, "%s %s [%s] %s%s", nodeNameStr, console.Colorize("Request", fmt.Sprintf("[%s %s]", strings.ToUpper(trc.TraceType.String()), trc.FuncName)), trc.Time.Local().Format(traceTimeFormat), trc.Message, extra) return b.String() default: + sz := "" + if trc.Bytes != 0 { + sz = fmt.Sprintf(" %s", humanize.IBytes(uint64(trc.Bytes))) + } if trc.Error != "" { - fmt.Fprintf(b, "%s %s [%s] %s%s err='%s' %s", nodeNameStr, console.Colorize("Request", fmt.Sprintf("[%s %s]", strings.ToUpper(trc.TraceType.String()), trc.FuncName)), trc.Time.Local().Format(traceTimeFormat), trc.Path, extra, console.Colorize("ErrStatus", trc.Error), trc.Duration) + fmt.Fprintf(b, "%s %s [%s] %s%s err='%s' %s%s", nodeNameStr, console.Colorize("Request", fmt.Sprintf("[%s %s]", strings.ToUpper(trc.TraceType.String()), trc.FuncName)), trc.Time.Local().Format(traceTimeFormat), trc.Path, extra, console.Colorize("ErrStatus", trc.Error), trc.Duration, sz) } else { - fmt.Fprintf(b, "%s %s [%s] %s%s %s", nodeNameStr, console.Colorize("Request", fmt.Sprintf("[%s %s]", strings.ToUpper(trc.TraceType.String()), trc.FuncName)), trc.Time.Local().Format(traceTimeFormat), trc.Path, extra, trc.Duration) + fmt.Fprintf(b, "%s %s [%s] %s%s %s%s", nodeNameStr, console.Colorize("Request", fmt.Sprintf("[%s %s]", strings.ToUpper(trc.TraceType.String()), trc.FuncName)), trc.Time.Local().Format(traceTimeFormat), trc.Path, extra, trc.Duration, sz) } return b.String() } @@ -903,6 +917,7 @@ type statItem struct { MaxTTFB time.Duration `json:"maxTTFB,omitempty"` MaxDur time.Duration `json:"maxDuration"` MinDur time.Duration `json:"minDuration"` + Size int64 `json:"size"` } type statTrace struct { @@ -951,6 +966,7 @@ func (s *statTrace) add(t madmin.ServiceTraceInfo) { if t.Trace.Error != "" { got.Errors++ } + got.Size += t.Trace.Bytes if t.Trace.HTTP != nil { got.CallStatsCount++ got.CallStats.Rx += t.Trace.HTTP.CallStats.InputBytes @@ -966,9 +982,10 @@ func (s *statTrace) add(t madmin.ServiceTraceInfo) { func initTraceStatsUI(maxEntries int, traces <-chan madmin.ServiceTraceInfo) *traceStatsUI { s := spinner.New() s.Spinner = spinner.Points - s.Spinner.FPS = time.Second / 4 + s.Spinner.FPS = time.Second / 2 s.Style = lipgloss.NewStyle().Foreground(lipgloss.Color("205")) console.SetColor("metrics-duration", color.New(color.FgWhite)) + console.SetColor("metrics-size", color.New(color.FgGreen)) console.SetColor("metrics-dur", color.New(color.FgGreen)) console.SetColor("metrics-dur-med", color.New(color.FgYellow)) console.SetColor("metrics-dur-high", color.New(color.FgRed)) @@ -1043,17 +1060,8 @@ func (m *traceStatsUI) View() string { table.SetRowSeparator("") table.SetHeaderLine(false) table.SetBorder(false) - table.SetTablePadding("\t") // pad with tabs + table.SetTablePadding(" ") // pad with tabs table.SetNoWhiteSpace(true) - addRow := func(s string) { - table.Append([]string{s}) - } - _ = addRow - addRowF := func(format string, vals ...interface{}) { - s := fmt.Sprintf(format, vals...) - table.Append([]string{s}) - } - _ = addRowF var entries []statItem m.current.mu.Lock() totalCnt := 0 @@ -1076,20 +1084,34 @@ func (m *traceStatsUI) View() string { if m.maxEntries > 0 && len(entries) > m.maxEntries { entries = entries[:m.maxEntries] } - - table.Append([]string{ + hasTTFB := false + for _, e := range entries { + if e.TTFB > 0 { + hasTTFB = true + break + } + } + t := []string{ console.Colorize("metrics-top-title", "Call"), console.Colorize("metrics-top-title", "Count"), console.Colorize("metrics-top-title", "RPM"), console.Colorize("metrics-top-title", "Avg Time"), console.Colorize("metrics-top-title", "Min Time"), console.Colorize("metrics-top-title", "Max Time"), - console.Colorize("metrics-top-title", "Avg TTFB"), - console.Colorize("metrics-top-title", "Max TTFB"), + } + if hasTTFB { + t = append(t, + console.Colorize("metrics-top-title", "Avg TTFB"), + console.Colorize("metrics-top-title", "Max TTFB"), + ) + } + t = append(t, + console.Colorize("metrics-top-title", "Avg Size"), + console.Colorize("metrics-top-title", "Rate"), console.Colorize("metrics-top-title", "Errors"), - console.Colorize("metrics-top-title", "RX Avg"), - console.Colorize("metrics-top-title", "TX Avg"), - }) + ) + + table.Append(t) for _, v := range entries { if v.Count <= 0 { continue @@ -1121,13 +1143,33 @@ func (m *traceStatsUI) View() string { maxColor = "metrics-dur-med" } - rx := "-" - tx := "-" + sz := "-" + rate := "-" + if v.Size > 0 && v.Count > 0 { + sz = humanize.IBytes(uint64(v.Size) / uint64(v.Count)) + rate = fmt.Sprintf("%s/m", humanize.IBytes(uint64(float64(v.Size)/dur.Minutes()))) + } if v.CallStatsCount > 0 { - rx = humanize.IBytes(uint64(v.CallStats.Rx / v.CallStatsCount)) - tx = humanize.IBytes(uint64(v.CallStats.Tx / v.CallStatsCount)) + var s, r []string + if v.CallStats.Rx > 0 { + s = append(s, fmt.Sprintf("↓%s", humanize.IBytes(uint64(v.CallStats.Rx/v.CallStatsCount)))) + r = append(r, fmt.Sprintf("↓%s", humanize.IBytes(uint64(float64(v.CallStats.Rx)/dur.Minutes())))) + } + if v.CallStats.Tx > 0 { + s = append(s, fmt.Sprintf("↑%s", humanize.IBytes(uint64(v.CallStats.Tx/v.CallStatsCount)))) + r = append(r, fmt.Sprintf("↑%s", humanize.IBytes(uint64(float64(v.CallStats.Tx)/dur.Minutes())))) + } + if len(s) > 0 { + sz = strings.Join(s, " ") + rate = strings.Join(r, " ") + "/m" + } } - table.Append([]string{ + if sz != "-" { + sz = console.Colorize("metrics-size", sz) + rate = console.Colorize("metrics-size", rate) + } + + t := []string{ console.Colorize("metrics-title", metricsTitle(v.Name)), console.Colorize("metrics-number", fmt.Sprintf("%d ", v.Count)) + console.Colorize("metrics-number-secondary", fmt.Sprintf("(%0.1f%%)", float64(v.Count)/float64(totalCnt)*100)), @@ -1135,13 +1177,28 @@ func (m *traceStatsUI) View() string { console.Colorize(avgColor, fmt.Sprintf("%v", avg.Round(time.Microsecond))), console.Colorize(minColor, v.MinDur), console.Colorize(maxColor, v.MaxDur), - console.Colorize(avgColor, fmt.Sprintf("%v", avgTTFB.Round(time.Microsecond))), - console.Colorize(maxColor, v.MaxTTFB), - errs, - rx, - tx, - }) + } + if hasTTFB { + t = append(t, + console.Colorize(avgColor, fmt.Sprintf("%v", avgTTFB.Round(time.Microsecond))), + console.Colorize(maxColor, v.MaxTTFB)) + } + t = append(t, sz, + rate, + errs) + table.Append(t) } table.Render() - return s.String() + if globalTermWidth <= 10 { + return s.String() + } + w := globalTermWidth + if nw, _, e := term.GetSize(int(os.Stdout.Fd())); e == nil { + w = nw + } + split := strings.Split(s.String(), "\n") + for i, line := range split { + split[i] = truncate.StringWithTail(line, uint(w), "»") + } + return strings.Join(split, "\n") } diff --git a/cmd/main.go b/cmd/main.go index 6c6061401e..a32c30599d 100644 --- a/cmd/main.go +++ b/cmd/main.go @@ -117,7 +117,7 @@ func Main(args []string) error { // Fetch terminal size, if not available, automatically // set globalQuiet to true on non-window. - if w, h, e := term.GetSize(int(os.Stdin.Fd())); e != nil { + if w, h, e := term.GetSize(int(os.Stdout.Fd())); e != nil { globalQuiet = runtime.GOOS != "windows" } else { globalTermWidth, globalTermHeight = w, h diff --git a/go.mod b/go.mod index 68690e7473..8f48a32cd6 100644 --- a/go.mod +++ b/go.mod @@ -41,7 +41,7 @@ require ( github.com/charmbracelet/lipgloss v0.10.0 github.com/golang-jwt/jwt/v4 v4.5.0 github.com/juju/ratelimit v1.0.2 - github.com/minio/madmin-go/v3 v3.0.51 + github.com/minio/madmin-go/v3 v3.0.55-0.20240603092915-420a67132c32 github.com/minio/pkg/v3 v3.0.0 github.com/minio/selfupdate v0.6.0 github.com/muesli/reflow v0.3.0 diff --git a/go.sum b/go.sum index 5c91c0ba5f..11d185a172 100644 --- a/go.sum +++ b/go.sum @@ -130,8 +130,8 @@ github.com/minio/colorjson v1.0.7 h1:n69M42mIuQHdzbsxlmwji1zxDypaw4o39rHjAmX4Dh4 github.com/minio/colorjson v1.0.7/go.mod h1:9LGM5yybI+GuhSbuzAerbSgvFb4j8ux9NzyONR+NrAY= github.com/minio/filepath v1.0.0 h1:fvkJu1+6X+ECRA6G3+JJETj4QeAYO9sV43I79H8ubDY= github.com/minio/filepath v1.0.0/go.mod h1:/nRZA2ldl5z6jT9/KQuvZcQlxZIMQoFFQPvEXx9T/Bw= -github.com/minio/madmin-go/v3 v3.0.51 h1:brGOvDP8KvoHb/bdzCHUPFCbTtrN8o507uPHZpyuinM= -github.com/minio/madmin-go/v3 v3.0.51/go.mod h1:IFAwr0XMrdsLovxAdCcuq/eoL4nRuMVQQv0iubJANQw= +github.com/minio/madmin-go/v3 v3.0.55-0.20240603092915-420a67132c32 h1:9se7/S4AlN2k/B1E7A8m1m07DM3p0JnIOzVhDuAV2PI= +github.com/minio/madmin-go/v3 v3.0.55-0.20240603092915-420a67132c32/go.mod h1:IFAwr0XMrdsLovxAdCcuq/eoL4nRuMVQQv0iubJANQw= github.com/minio/md5-simd v1.1.2 h1:Gdi1DZK69+ZVMoNHRXJyNcxrMA4dSxoYHZSQbirFg34= github.com/minio/md5-simd v1.1.2/go.mod h1:MzdKDxYpY2BT9XQFocsiZf/NKVtR7nkE4RoEpN+20RM= github.com/minio/minio-go/v7 v7.0.70 h1:1u9NtMgfK1U42kUxcsl5v0yj6TEOPR497OAQxpJnn2g=