From edd04bdf9205bbb9504f99601adc0c51ebd2362b Mon Sep 17 00:00:00 2001 From: debugtalk Date: Tue, 3 May 2022 23:37:23 +0800 Subject: [PATCH] feat: stat HTTP request latencies (DNSLookup, TCP Connection and so on) --- docs/CHANGELOG.md | 3 +- docs/cmd/hrp.md | 2 +- docs/cmd/hrp_boom.md | 2 +- docs/cmd/hrp_convert.md | 2 +- docs/cmd/hrp_har2case.md | 2 +- docs/cmd/hrp_pytest.md | 2 +- docs/cmd/hrp_run.md | 3 +- docs/cmd/hrp_startproject.md | 2 +- hrp/cmd/run.go | 5 + hrp/internal/httpstat/main.go | 169 ++++++++++++++++++++++++++++++++++ hrp/runner.go | 8 ++ hrp/session.go | 4 + hrp/step.go | 19 ++-- hrp/step_request.go | 16 ++++ 14 files changed, 223 insertions(+), 16 deletions(-) create mode 100644 hrp/internal/httpstat/main.go diff --git a/docs/CHANGELOG.md b/docs/CHANGELOG.md index 51fb4192..e67c879e 100644 --- a/docs/CHANGELOG.md +++ b/docs/CHANGELOG.md @@ -1,9 +1,10 @@ # Release History -## v4.0.0 (2022-05-03) +## v4.0.0 (2022-05-04) **go version** +- feat: stat HTTP request latencies (DNSLookup, TCP Connection and so on) - feat: add builtin function `environ`/`ENV` - fix: demo function compatibility - fix #1240: losing host port in har2case diff --git a/docs/cmd/hrp.md b/docs/cmd/hrp.md index ef528f9d..ce94ba75 100644 --- a/docs/cmd/hrp.md +++ b/docs/cmd/hrp.md @@ -36,4 +36,4 @@ Copyright 2017 debugtalk * [hrp run](hrp_run.md) - run API test with go engine * [hrp startproject](hrp_startproject.md) - create a scaffold project -###### Auto generated by spf13/cobra on 3-May-2022 +###### Auto generated by spf13/cobra on 4-May-2022 diff --git a/docs/cmd/hrp_boom.md b/docs/cmd/hrp_boom.md index fe95ddab..4344710a 100644 --- a/docs/cmd/hrp_boom.md +++ b/docs/cmd/hrp_boom.md @@ -41,4 +41,4 @@ hrp boom [flags] * [hrp](hrp.md) - Next-Generation API Testing Solution. -###### Auto generated by spf13/cobra on 3-May-2022 +###### Auto generated by spf13/cobra on 4-May-2022 diff --git a/docs/cmd/hrp_convert.md b/docs/cmd/hrp_convert.md index 880bce0b..2010b694 100644 --- a/docs/cmd/hrp_convert.md +++ b/docs/cmd/hrp_convert.md @@ -18,4 +18,4 @@ hrp convert $path... [flags] * [hrp](hrp.md) - Next-Generation API Testing Solution. -###### Auto generated by spf13/cobra on 3-May-2022 +###### Auto generated by spf13/cobra on 4-May-2022 diff --git a/docs/cmd/hrp_har2case.md b/docs/cmd/hrp_har2case.md index d7b6e925..3fd38c9d 100644 --- a/docs/cmd/hrp_har2case.md +++ b/docs/cmd/hrp_har2case.md @@ -24,4 +24,4 @@ hrp har2case $har_path... [flags] * [hrp](hrp.md) - Next-Generation API Testing Solution. -###### Auto generated by spf13/cobra on 3-May-2022 +###### Auto generated by spf13/cobra on 4-May-2022 diff --git a/docs/cmd/hrp_pytest.md b/docs/cmd/hrp_pytest.md index 5c59d217..29678585 100644 --- a/docs/cmd/hrp_pytest.md +++ b/docs/cmd/hrp_pytest.md @@ -16,4 +16,4 @@ hrp pytest $path ... [flags] * [hrp](hrp.md) - Next-Generation API Testing Solution. -###### Auto generated by spf13/cobra on 3-May-2022 +###### Auto generated by spf13/cobra on 4-May-2022 diff --git a/docs/cmd/hrp_run.md b/docs/cmd/hrp_run.md index 6d2f8486..86c7018d 100644 --- a/docs/cmd/hrp_run.md +++ b/docs/cmd/hrp_run.md @@ -24,6 +24,7 @@ hrp run $path... [flags] -c, --continue-on-failure continue running next step when failure occurs -g, --gen-html-report generate html report -h, --help help for run + --http-stat turn on HTTP latency stat (DNSLookup, TCP Connection, etc.) --log-plugin turn on plugin logging --log-requests-off turn off request & response details logging -p, --proxy-url string set proxy url @@ -34,4 +35,4 @@ hrp run $path... [flags] * [hrp](hrp.md) - Next-Generation API Testing Solution. -###### Auto generated by spf13/cobra on 3-May-2022 +###### Auto generated by spf13/cobra on 4-May-2022 diff --git a/docs/cmd/hrp_startproject.md b/docs/cmd/hrp_startproject.md index a8706619..95fa28e6 100644 --- a/docs/cmd/hrp_startproject.md +++ b/docs/cmd/hrp_startproject.md @@ -20,4 +20,4 @@ hrp startproject $project_name [flags] * [hrp](hrp.md) - Next-Generation API Testing Solution. -###### Auto generated by spf13/cobra on 3-May-2022 +###### Auto generated by spf13/cobra on 4-May-2022 diff --git a/hrp/cmd/run.go b/hrp/cmd/run.go index 17f54014..891563fd 100644 --- a/hrp/cmd/run.go +++ b/hrp/cmd/run.go @@ -35,6 +35,9 @@ var runCmd = &cobra.Command{ if !requestsLogOff { runner.SetRequestsLogOn() } + if httpStatOn { + runner.SetHTTPStatOn() + } if pluginLogOn { runner.SetPluginLogOn() } @@ -51,6 +54,7 @@ var runCmd = &cobra.Command{ var ( continueOnFailure bool requestsLogOff bool + httpStatOn bool pluginLogOn bool proxyUrl string saveTests bool @@ -61,6 +65,7 @@ func init() { rootCmd.AddCommand(runCmd) runCmd.Flags().BoolVarP(&continueOnFailure, "continue-on-failure", "c", false, "continue running next step when failure occurs") runCmd.Flags().BoolVar(&requestsLogOff, "log-requests-off", false, "turn off request & response details logging") + runCmd.Flags().BoolVar(&httpStatOn, "http-stat", false, "turn on HTTP latency stat (DNSLookup, TCP Connection, etc.)") runCmd.Flags().BoolVar(&pluginLogOn, "log-plugin", false, "turn on plugin logging") runCmd.Flags().StringVarP(&proxyUrl, "proxy-url", "p", "", "set proxy url") runCmd.Flags().BoolVarP(&saveTests, "save-tests", "s", false, "save tests summary") diff --git a/hrp/internal/httpstat/main.go b/hrp/internal/httpstat/main.go new file mode 100644 index 00000000..1d9a1a5e --- /dev/null +++ b/hrp/internal/httpstat/main.go @@ -0,0 +1,169 @@ +// 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 +package httpstat + +import ( + "context" + "crypto/tls" + "net/http/httptrace" + "time" +) + +// Stat stores httpstat info. +type Stat struct { + // The following are duration for each phase + // DNSLookup => TCPConnection => TLSHandshake => ServerProcessing => ContentTransfer + DNSLookup time.Duration + TCPConnection time.Duration + TLSHandshake time.Duration + ServerProcessing time.Duration + ContentTransfer time.Duration // from the first response byte to tansfer done. + + // The followings are timeline of request + NameLookup time.Duration // = DNSLookup + Connect time.Duration // = DNSLookup + TCPConnection + Pretransfer time.Duration // = DNSLookup + TCPConnection + TLSHandshake + StartTransfer time.Duration // = DNSLookup + TCPConnection + TLSHandshake + ServerProcessing + Total time.Duration // = DNSLookup + TCPConnection + TLSHandshake + ServerProcessing + ContentTransfer + + // internal timelines, including start and finish timestamps of each phase + dnsStart time.Time + dnsDone time.Time + tcpStart time.Time + tcpDone time.Time + tlsStart time.Time + tlsDone time.Time + serverStart time.Time + serverDone time.Time + transferStart time.Time + transferDone time.Time // need to be provided from outside + + // isTLS is true when connection seems to use TLS + isTLS bool + + // isReused is true when connection is reused (keep-alive) + isReused bool +} + +// Finish sets the time when reading response is done. +// This must be called after reading response body. +func (s *Stat) Finish() { + s.transferDone = time.Now() + + // This means result is empty (it does nothing). + // Skip setting value (contentTransfer and total will be zero). + if s.dnsStart.IsZero() { + return + } + + s.ContentTransfer = s.transferDone.Sub(s.transferStart) + s.Total = s.transferDone.Sub(s.dnsStart) +} + +// Durations returns all durations and timelines of request latencies +func (s *Stat) Durations() map[string]time.Duration { + return map[string]time.Duration{ + "DNSLookup": s.DNSLookup / time.Millisecond, + "TCPConnection": s.TCPConnection / time.Millisecond, + "TLSHandshake": s.TLSHandshake / time.Millisecond, + "ServerProcessing": s.ServerProcessing / time.Millisecond, + "ContentTransfer": s.ContentTransfer / time.Millisecond, + "NameLookup": s.NameLookup / time.Millisecond, + "Connect": s.Connect / time.Millisecond, + "Pretransfer": s.Connect / time.Millisecond, + "StartTransfer": s.StartTransfer / time.Millisecond, + "Total": s.Total / time.Millisecond, + } +} + +// WithHTTPStat is a wrapper of httptrace.WithClientTrace. +// It records the time of each httptrace hooks. +func WithHTTPStat(ctx context.Context, s *Stat) context.Context { + return httptrace.WithClientTrace(ctx, &httptrace.ClientTrace{ + DNSStart: func(i httptrace.DNSStartInfo) { + s.dnsStart = time.Now() + }, + + DNSDone: func(i httptrace.DNSDoneInfo) { + s.dnsDone = time.Now() + + s.DNSLookup = s.dnsDone.Sub(s.dnsStart) + s.NameLookup = s.dnsDone.Sub(s.dnsStart) + }, + + ConnectStart: func(_, _ string) { + s.tcpStart = time.Now() + + // When connecting to IP (When no DNS lookup) + if s.dnsStart.IsZero() { + s.dnsStart = s.tcpStart + s.dnsDone = s.tcpStart + } + }, + + ConnectDone: func(network, addr string, err error) { + s.tcpDone = time.Now() + s.TCPConnection = s.tcpDone.Sub(s.tcpStart) + s.Connect = s.tcpDone.Sub(s.dnsStart) + }, + + TLSHandshakeStart: func() { + s.isTLS = true + s.tlsStart = time.Now() + }, + + TLSHandshakeDone: func(_ tls.ConnectionState, _ error) { + s.tlsDone = time.Now() + s.TLSHandshake = s.tlsDone.Sub(s.tlsStart) + s.Pretransfer = s.tlsDone.Sub(s.dnsStart) + }, + + GotConn: func(i httptrace.GotConnInfo) { + // Handle when keep alive is used and connection is reused. + // DNSStart(Done) and ConnectStart(Done) is skipped + if i.Reused { + s.isReused = true + } + }, + + WroteRequest: func(info httptrace.WroteRequestInfo) { + s.serverStart = time.Now() + + // 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() { + now := s.serverStart + s.dnsStart = now + s.dnsDone = now + s.tcpStart = now + s.tcpDone = now + } + + // When connection is re-used, DNS/TCP/TLS hook is not called. + if s.isReused { + now := s.serverStart + s.dnsStart = now + s.dnsDone = now + s.tcpStart = now + s.tcpDone = now + s.tlsStart = now + s.tlsDone = now + } + + if s.isTLS { + return + } + + s.TLSHandshake = s.tcpDone.Sub(s.tcpDone) + s.Pretransfer = s.Connect + }, + + GotFirstResponseByte: func() { + s.serverDone = time.Now() + s.ServerProcessing = s.serverDone.Sub(s.serverStart) + s.StartTransfer = s.serverDone.Sub(s.dnsStart) + s.transferStart = s.serverDone + }, + }) +} diff --git a/hrp/runner.go b/hrp/runner.go index d21b8beb..74c463cd 100644 --- a/hrp/runner.go +++ b/hrp/runner.go @@ -54,6 +54,7 @@ func NewRunner(t *testing.T) *HRPRunner { type HRPRunner struct { t *testing.T failfast bool + httpStatOn bool requestsLogOn bool pluginLogOn bool saveTests bool @@ -100,6 +101,13 @@ func (r *HRPRunner) SetRequestsLogOn() *HRPRunner { return r } +// SetHTTPStatOn turns on HTTP latency stat. +func (r *HRPRunner) SetHTTPStatOn() *HRPRunner { + log.Info().Msg("[init] SetHTTPStatOn") + r.httpStatOn = true + return r +} + // SetPluginLogOn turns on plugin logging. func (r *HRPRunner) SetPluginLogOn() *HRPRunner { log.Info().Msg("[init] SetPluginLogOn") diff --git a/hrp/session.go b/hrp/session.go index 96710284..eae3b41a 100644 --- a/hrp/session.go +++ b/hrp/session.go @@ -42,6 +42,10 @@ func (r *SessionRunner) GetConfig() *TConfig { return r.parsedConfig } +func (r *SessionRunner) HTTPStatOn() bool { + return r.hrpRunner.httpStatOn +} + func (r *SessionRunner) LogOn() bool { return r.hrpRunner.requestsLogOn } diff --git a/hrp/step.go b/hrp/step.go index 242f9294..4ee91355 100644 --- a/hrp/step.go +++ b/hrp/step.go @@ -1,5 +1,7 @@ package hrp +import "time" + type StepType string const ( @@ -13,14 +15,15 @@ const ( ) type StepResult struct { - Name string `json:"name" yaml:"name"` // step name - 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) - 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 - Attachment string `json:"attachment,omitempty" yaml:"attachment,omitempty"` // step error information + Name string `json:"name" yaml:"name"` // step name + 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]time.Duration `json:"httpstat" yaml:"httpstat"` // 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 + Attachment string `json:"attachment,omitempty" yaml:"attachment,omitempty"` // step error information } // TStep represents teststep data structure. diff --git a/hrp/step_request.go b/hrp/step_request.go index 64994657..d1b9e7a8 100644 --- a/hrp/step_request.go +++ b/hrp/step_request.go @@ -19,6 +19,7 @@ import ( "github.com/rs/zerolog/log" "github.com/httprunner/httprunner/hrp/internal/builtin" + "github.com/httprunner/httprunner/hrp/internal/httpstat" "github.com/httprunner/httprunner/hrp/internal/json" ) @@ -311,6 +312,13 @@ func runStepRequest(r *SessionRunner, step *TStep) (stepResult *StepResult, err } } + // stat HTTP request + var httpStat httpstat.Stat + if r.HTTPStatOn() { + ctx := httpstat.WithHTTPStat(rb.req.Context(), &httpStat) + rb.req = rb.req.WithContext(ctx) + } + // do request action start := time.Now() var resp *http.Response @@ -339,6 +347,14 @@ 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") + } + // new response object respObj, err := newHttpResponseObject(r.hrpRunner.t, parser, resp) if err != nil {