From 0bd8cf39eafc022c43b72dbb3aee8d564ac80239 Mon Sep 17 00:00:00 2001 From: debugtalk Date: Thu, 5 May 2022 14:24:48 +0800 Subject: [PATCH] feat: print http stat with color --- go.mod | 1 + go.sum | 4 +- hrp/internal/httpstat/main.go | 93 +++++++++++++++++++++++++++++++++-- hrp/step.go | 2 +- hrp/step_request.go | 4 +- hrp/step_request_test.go | 20 ++++---- 6 files changed, 106 insertions(+), 18 deletions(-) diff --git a/go.mod b/go.mod index 510515e6..cdba9350 100644 --- a/go.mod +++ b/go.mod @@ -5,6 +5,7 @@ go 1.16 require ( github.com/andybalholm/brotli v1.0.4 github.com/denisbrodbeck/machineid v1.0.1 + github.com/fatih/color v1.13.0 github.com/getsentry/sentry-go v0.13.0 github.com/google/uuid v1.3.0 github.com/gorilla/websocket v1.4.1 diff --git a/go.sum b/go.sum index 24c26644..e72fb518 100644 --- a/go.sum +++ b/go.sum @@ -106,8 +106,9 @@ github.com/envoyproxy/go-control-plane v0.9.9-0.20210217033140-668b12f5399d/go.m github.com/envoyproxy/go-control-plane v0.9.10-0.20210907150352-cf90f659a021/go.mod h1:AFq3mo9L8Lqqiid3OhADV3RfLJnjiw63cSpi+fDTRC0= github.com/envoyproxy/protoc-gen-validate v0.1.0/go.mod h1:iSmxcyjqTsJpI2R4NaDN7+kN2VEUnK/pcBlmesArF7c= github.com/etcd-io/bbolt v1.3.3/go.mod h1:ZF2nL25h33cCyBtcyWeZ2/I3HQOfTP+0PIEvHjkjCrw= -github.com/fatih/color v1.7.0 h1:DkWD4oS2D8LGGgTQ6IvwJJXSL5Vp2ffcQg58nFV38Ys= github.com/fatih/color v1.7.0/go.mod h1:Zm6kSWBoL9eyXnKyktHP6abPY2pDugNf5KwzbycvMj4= +github.com/fatih/color v1.13.0 h1:8LOYc1KYPPmyKMuN8QV2DNRWNbLo6LZ0iLs8+mlH53w= +github.com/fatih/color v1.13.0/go.mod h1:kLAiJbzzSOZDVNGyDpeOxJ47H46qBXwg5ILebYFFOfk= github.com/fatih/structs v1.1.0/go.mod h1:9NiDSp5zOcgEDl+j00MP/WkGVPOlPRLejGD8Ga6PJ7M= github.com/fsnotify/fsnotify v1.4.7/go.mod h1:jwhsz4b93w/PPRr/qN1Yymfu8t87LnFCMoQvtojpjFo= github.com/fsnotify/fsnotify v1.4.9/go.mod h1:znqG4EE+3YCdAaPaxE2ZRY/06pZUdp0tY4IgpuI1SZQ= @@ -303,6 +304,7 @@ github.com/mattn/go-colorable v0.0.9/go.mod h1:9vuHe8Xs5qXnSaW/c/ABM9alt+Vo+STaO github.com/mattn/go-colorable v0.1.2/go.mod h1:U0ppj6V5qS13XJ6of8GYAs25YV2eR4EVcfRqFIhoBtE= github.com/mattn/go-colorable v0.1.4/go.mod h1:U0ppj6V5qS13XJ6of8GYAs25YV2eR4EVcfRqFIhoBtE= github.com/mattn/go-colorable v0.1.8/go.mod h1:u6P/XSegPjTcexA+o6vUJrdnUu04hMope9wVRipJSqc= +github.com/mattn/go-colorable v0.1.9/go.mod h1:u6P/XSegPjTcexA+o6vUJrdnUu04hMope9wVRipJSqc= github.com/mattn/go-colorable v0.1.11 h1:nQ+aFkoE2TMGc0b68U2OKSexC+eq46+XwZzWXHRmPYs= github.com/mattn/go-colorable v0.1.11/go.mod h1:u5H1YNBxpqRaxsYJYSkiCWKzEfiAb1Gb520KVy5xxl4= github.com/mattn/go-isatty v0.0.3/go.mod h1:M+lRXTBqGeGNdLjl/ufCoiOlB5xdOkqRJdNxMWT7Zi4= diff --git a/hrp/internal/httpstat/main.go b/hrp/internal/httpstat/main.go index 765e7171..8d8ccc0d 100644 --- a/hrp/internal/httpstat/main.go +++ b/hrp/internal/httpstat/main.go @@ -1,15 +1,64 @@ // Package httpstat traces HTTP latency infomation (DNSLookup, TCP Connection and so on) on any golang HTTP request. // It uses `httptrace` package. -// Forked from https://github.com/tcnksm/go-httpstat +// Inspired by https://github.com/tcnksm/go-httpstat and https://github.com/davecheney/httpstat package httpstat import ( "context" "crypto/tls" + "fmt" "net/http/httptrace" + "strconv" + "strings" "time" + + "github.com/fatih/color" + "github.com/rs/zerolog/log" ) +const ( + httpsTemplate = "\n" + + ` DNS Lookup TCP Connection TLS Handshake Server Processing Content Transfer` + "\n" + + `[%s | %s | %s | %s | %s ]` + "\n" + + ` | | | | |` + "\n" + + ` namelookup:%s | | | |` + "\n" + + ` connect:%s | | |` + "\n" + + ` pretransfer:%s | |` + "\n" + + ` starttransfer:%s |` + "\n" + + ` total:%s` + "\n\n" + + httpTemplate = "\n" + + ` DNS Lookup TCP Connection Server Processing Content Transfer` + "\n" + + `[ %s | %s | %s | %s ]` + "\n" + + ` | | | |` + "\n" + + ` namelookup:%s | | |` + "\n" + + ` connect:%s | |` + "\n" + + ` starttransfer:%s |` + "\n" + + ` total:%s` + "\n\n" +) + +func fmta(d time.Duration) string { + return color.BlueString("%7dms", int(d.Milliseconds())) +} + +func fmtb(d time.Duration) string { + return color.MagentaString("%-9s", strconv.Itoa(int(d.Milliseconds()))+"ms") +} + +func grayscale(code color.Attribute) func(string, ...interface{}) string { + return color.New(code + 232).SprintfFunc() +} + +func colorize(s string) string { + v := strings.Split(s, "\n") + v[0] = grayscale(16)(v[0]) + return strings.Join(v, "\n") +} + +func printf(format string, a ...interface{}) (n int, err error) { + return fmt.Fprintf(color.Output, format, a...) +} + // Stat stores httpstat info. type Stat struct { // The following are duration for each phase @@ -61,6 +110,11 @@ func (s *Stat) Finish() { s.Total = s.transferDone.Sub(s.dnsStart) } +func (s *Stat) assertSchemaHTTP() bool { + // HTTP other than HTTPS + return s.dnsStart.IsZero() && s.tcpStart.IsZero() +} + // Durations returns all durations and timelines of request latencies func (s *Stat) Durations() map[string]int64 { return map[string]int64{ @@ -71,12 +125,45 @@ func (s *Stat) Durations() map[string]int64 { "ContentTransfer": s.ContentTransfer.Milliseconds(), "NameLookup": s.NameLookup.Milliseconds(), "Connect": s.Connect.Milliseconds(), - "Pretransfer": s.Connect.Milliseconds(), + "Pretransfer": s.Pretransfer.Milliseconds(), "StartTransfer": s.StartTransfer.Milliseconds(), "Total": s.Total.Milliseconds(), } } +func (s *Stat) Print() { + if s.assertSchemaHTTP() { + // http + printf(colorize(httpTemplate), + fmta(s.DNSLookup), // dns lookup + fmta(s.TCPConnection), // tcp connection + fmta(s.ServerProcessing), // server processing + fmta(s.ContentTransfer), // content transfer + fmtb(s.NameLookup), // namelookup + fmtb(s.Connect), // connect + fmtb(s.StartTransfer), // starttransfer + fmtb(s.Total), // total + ) + } else { + // https + printf(colorize(httpsTemplate), + fmta(s.DNSLookup), // dns lookup + fmta(s.TCPConnection), // tcp connection + fmta(s.TLSHandshake), // tls handshake + fmta(s.ServerProcessing), // server processing + fmta(s.ContentTransfer), // content transfer + fmtb(s.NameLookup), // namelookup + fmtb(s.Connect), // connect + fmtb(s.Pretransfer), // pretransfer + fmtb(s.StartTransfer), // starttransfer + fmtb(s.Total), // total + ) + } + log.Info(). + Interface("httpstat(ms)", s.Durations()). + Msg("HTTP latency statistics") +} + // WithHTTPStat is a wrapper of httptrace.WithClientTrace. // It records the time of each httptrace hooks. func WithHTTPStat(ctx context.Context, s *Stat) context.Context { @@ -132,7 +219,7 @@ func WithHTTPStat(ctx context.Context, s *Stat) context.Context { // When client doesn't use DialContext or using old (before go1.7) `net` // package, DNS/TCP/TLS hook is not called. - if s.dnsStart.IsZero() && s.tcpStart.IsZero() { + if s.assertSchemaHTTP() { now := s.serverStart s.dnsStart = now s.dnsDone = now diff --git a/hrp/step.go b/hrp/step.go index 8a9d0031..b4583852 100644 --- a/hrp/step.go +++ b/hrp/step.go @@ -17,7 +17,7 @@ type StepResult struct { StepType StepType `json:"step_type" yaml:"step_type"` // step type, testcase/request/transaction/rendezvous Success bool `json:"success" yaml:"success"` // step execution result Elapsed int64 `json:"elapsed_ms" yaml:"elapsed_ms"` // step execution time in millisecond(ms) - HttpStat map[string]int64 `json:"httpstat" yaml:"httpstat"` // httpstat in millisecond(ms) + HttpStat map[string]int64 `json:"httpstat,omitempty" yaml:"httpstat,omitempty"` // httpstat in millisecond(ms) Data interface{} `json:"data,omitempty" yaml:"data,omitempty"` // session data or slice of step data ContentSize int64 `json:"content_size" yaml:"content_size"` // response body length ExportVars map[string]interface{} `json:"export_vars,omitempty" yaml:"export_vars,omitempty"` // extract variables diff --git a/hrp/step_request.go b/hrp/step_request.go index d1b9e7a8..9dbae164 100644 --- a/hrp/step_request.go +++ b/hrp/step_request.go @@ -350,9 +350,7 @@ func runStepRequest(r *SessionRunner, step *TStep) (stepResult *StepResult, err if r.HTTPStatOn() { httpStat.Finish() stepResult.HttpStat = httpStat.Durations() - log.Info(). - Interface("httpstat(ms)", httpStat.Durations()). - Msg("HTTP latency statistics") + httpStat.Print() } // new response object diff --git a/hrp/step_request_test.go b/hrp/step_request_test.go index 795595b1..8a88e3bb 100644 --- a/hrp/step_request_test.go +++ b/hrp/step_request_test.go @@ -105,31 +105,31 @@ func TestRunRequestStatOn(t *testing.T) { summary := sessionRunner.GetSummary() stat := summary.Records[0].HttpStat - if !assert.Greater(t, stat["DNSLookup"], int64(1)) { + if !assert.Greater(t, stat["DNSLookup"], int64(0)) { t.Fatal() } - if !assert.Greater(t, stat["TCPConnection"], int64(1)) { + if !assert.Greater(t, stat["TCPConnection"], int64(0)) { t.Fatal() } - if !assert.Greater(t, stat["TLSHandshake"], int64(1)) { + if !assert.Greater(t, stat["TLSHandshake"], int64(0)) { t.Fatal() } - if !assert.Greater(t, stat["ServerProcessing"], int64(1)) { + if !assert.Greater(t, stat["ServerProcessing"], int64(10)) { t.Fatal() } if !assert.GreaterOrEqual(t, stat["ContentTransfer"], int64(0)) { t.Fatal() } - if !assert.Greater(t, stat["NameLookup"], int64(1)) { + if !assert.Greater(t, stat["NameLookup"], int64(0)) { t.Fatal() } - if !assert.Greater(t, stat["Connect"], int64(1)) { + if !assert.Greater(t, stat["Connect"], int64(0)) { t.Fatal() } - if !assert.Greater(t, stat["Pretransfer"], int64(1)) { + if !assert.Greater(t, stat["Pretransfer"], int64(0)) { t.Fatal() } - if !assert.Greater(t, stat["StartTransfer"], int64(1)) { + if !assert.Greater(t, stat["StartTransfer"], int64(0)) { t.Fatal() } if !assert.Greater(t, stat["Total"], int64(10)) { @@ -150,7 +150,7 @@ func TestRunRequestStatOn(t *testing.T) { if !assert.Equal(t, stat["TLSHandshake"], int64(0)) { t.Fatal() } - if !assert.Greater(t, stat["ServerProcessing"], int64(1)) { + if !assert.Greater(t, stat["ServerProcessing"], int64(10)) { t.Fatal() } if !assert.Equal(t, stat["ContentTransfer"], int64(0)) { @@ -165,7 +165,7 @@ func TestRunRequestStatOn(t *testing.T) { if !assert.Equal(t, stat["Pretransfer"], int64(0)) { t.Fatal() } - if !assert.Greater(t, stat["StartTransfer"], int64(10)) { + if !assert.Greater(t, stat["StartTransfer"], int64(0)) { t.Fatal() } if !assert.Greater(t, stat["Total"], int64(10)) {