feat: stat HTTP request latencies (DNSLookup, TCP Connection and so on)

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

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

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

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

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

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

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

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

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")

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
+		},
+	})
+}

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")

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
 }

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
+	Name        string                   `json:"name" yaml:"name"`                                   // step name
-	StepType    StepType               `json:"step_type" yaml:"step_type"`                         // step type, testcase/request/transaction/rendezvous
+	StepType    StepType                 `json:"step_type" yaml:"step_type"`                         // step type, testcase/request/transaction/rendezvous
-	Success     bool                   `json:"success" yaml:"success"`                             // step execution result
+	Success     bool                     `json:"success" yaml:"success"`                             // step execution result
-	Elapsed     int64                  `json:"elapsed_ms" yaml:"elapsed_ms"`                       // step execution time in millisecond(ms)
+	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
+	HttpStat    map[string]time.Duration `json:"httpstat" yaml:"httpstat"`                           // httpstat in millisecond(ms)
-	ContentSize int64                  `json:"content_size" yaml:"content_size"`                   // response body length
+	Data        interface{}              `json:"data,omitempty" yaml:"data,omitempty"`               // session data or slice of step data
-	ExportVars  map[string]interface{} `json:"export_vars,omitempty" yaml:"export_vars,omitempty"` // extract variables
+	ContentSize int64                    `json:"content_size" yaml:"content_size"`                   // response body length
-	Attachment  string                 `json:"attachment,omitempty" yaml:"attachment,omitempty"`   // step error information
+	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.

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 {