From 72e40911819f9a41013272a4cda381e96bdbf8d5 Mon Sep 17 00:00:00 2001 From: Jason Del Ponte Date: Wed, 22 Jul 2020 09:28:19 -0700 Subject: [PATCH] example/aws/request/httptrace: Update example with more metrics (#3436) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Updates the tracing example to include additional metrics such as SDKs request handlers, and support multiple request attempts. Connection created: ``` 2020/07/21 15:39:07 Latency: 278.508656ms, Validate: 19.515µs, Build: 190.755µs, Attempts: 1, Attempt: 0, Latency: 278.240054ms, Sign: 453.163µs, Send: 277.580235ms, Unmarshal: 202.311µs, WillRetry: false, HTTP: Latency: 277.580856ms, ConnReused: false, GetConn: 225.662398ms, WriteRequest: 325.956µs, WaitResponseFirstByte: 277.509316ms, ReadResponseHeader: 71.234µs, Conn: DNS: 20.385136ms, Connect: 14.947772ms, TLS: 189.910822ms ``` Connection re-used: ``` 2020/07/21 15:39:09 Latency: 101.936094ms, Validate: 2.644µs, Build: 67.157µs, Attempts: 1, Attempt: 0, Latency: 101.836442ms, Sign: 122.098µs, Send: 101.517516ms, Unmarshal: 191.31µs, WillRetry: false, HTTP: Latency: 101.518147ms, ConnReused: true, GetConn: 38.265µs, WriteRequest: 178.058µs, WaitResponseFirstByte: 101.457147ms, ReadResponseHeader: 60.526µs, ``` --- CHANGELOG_PENDING.md | 2 + example/aws/request/httptrace/README.md | 24 +- example/aws/request/httptrace/logger.go | 100 ------ example/aws/request/httptrace/main.go | 16 +- example/aws/request/httptrace/trace.go | 427 +++++++++++++++++++++--- 5 files changed, 404 insertions(+), 165 deletions(-) delete mode 100644 example/aws/request/httptrace/logger.go diff --git a/CHANGELOG_PENDING.md b/CHANGELOG_PENDING.md index 8a1927a39ca..1d65d7c80c1 100644 --- a/CHANGELOG_PENDING.md +++ b/CHANGELOG_PENDING.md @@ -1,5 +1,7 @@ ### SDK Features ### SDK Enhancements +* `example/aws/request/httptrace`: Update example with more metrics ([#3436](https://github.com/aws/aws-sdk-go/pull/3436)) + * Updates the tracing example to include additional metrics such as SDKs request handlers, and support multiple request attempts. ### SDK Bugs diff --git a/example/aws/request/httptrace/README.md b/example/aws/request/httptrace/README.md index 22bd428b028..55e72b8c1ae 100644 --- a/example/aws/request/httptrace/README.md +++ b/example/aws/request/httptrace/README.md @@ -7,9 +7,6 @@ like SNS's `PublishWithContext`. The `trace.go` file demonstrates how the `httptrace` package's `ClientTrace` can be created to gather timing information from HTTP requests made. -The `logger.go` file demonstrates how the trace information can be combined to -retrieve timing data for the different stages of the request. - The `config.go` file provides additional configuration settings to control how the HTTP client and its transport is configured. Such as, timeouts, and keepalive. @@ -36,5 +33,24 @@ Message: My Really cool Message The example will output the http trace timing information for how long the request took. ``` -Latency: 79.863505ms ConnectionReused: false DNSStartAt: 280.452µs DNSDoneAt: 1.526342ms DNSDur: 1.24589ms ConnectStartAt: 1.533484ms ConnectDoneAt: 11.290792ms ConnectDur: 9.757308ms TLSStatAt: 11.331066ms TLSDoneAt: 33.912968ms TLSDur: 22.581902ms RequestWritten 34.951272ms RespFirstByte: 79.534808ms WaitRespFirstByte: 44.583536ms +2020/07/21 15:39:07 Latency: 278.508656ms, Validate: 19.515µs, Build: 190.755µs, Attempts: 1, + Attempt: 0, Latency: 278.240054ms, Sign: 453.163µs, Send: 277.580235ms, Unmarshal: 202.311µs, WillRetry: false, + HTTP: Latency: 277.580856ms, ConnReused: false, GetConn: 225.662398ms, WriteRequest: 325.956µs, WaitResponseFirstByte: 277.509316ms, ReadResponseHeader: 71.234µs, + Conn: DNS: 20.385136ms, Connect: 14.947772ms, TLS: 189.910822ms, + +Message: second +2020/07/21 15:39:09 Latency: 101.936094ms, Validate: 2.644µs, Build: 67.157µs, Attempts: 1, + Attempt: 0, Latency: 101.836442ms, Sign: 122.098µs, Send: 101.517516ms, Unmarshal: 191.31µs, WillRetry: false, + HTTP: Latency: 101.518147ms, ConnReused: true, GetConn: 38.265µs, WriteRequest: 178.058µs, WaitResponseFirstByte: 101.457147ms, ReadResponseHeader: 60.526µs, + +Message: thrid +2020/07/21 15:39:10 Latency: 32.373919ms, Validate: 2.998µs, Build: 39.136µs, Attempts: 1, + Attempt: 0, Latency: 32.295677ms, Sign: 104.978µs, Send: 32.040306ms, Unmarshal: 146.096µs, WillRetry: false, + HTTP: Latency: 32.04078ms, ConnReused: true, GetConn: 33.36µs, WriteRequest: 166.508µs, WaitResponseFirstByte: 31.980933ms, ReadResponseHeader: 59.235µs, + +Message: fourth +2020/07/21 15:39:13 Latency: 33.353819ms, Validate: 2.002µs, Build: 36.807µs, Attempts: 1, + Attempt: 0, Latency: 33.29846ms, Sign: 70.238µs, Send: 33.125914ms, Unmarshal: 98.181µs, WillRetry: false, + HTTP: Latency: 33.126453ms, ConnReused: true, GetConn: 47.516µs, WriteRequest: 251.875µs, WaitResponseFirstByte: 33.05992ms, ReadResponseHeader: 66.017µs, ``` + diff --git a/example/aws/request/httptrace/logger.go b/example/aws/request/httptrace/logger.go deleted file mode 100644 index bbab5ec98fc..00000000000 --- a/example/aws/request/httptrace/logger.go +++ /dev/null @@ -1,100 +0,0 @@ -// build example - -package main - -import ( - "fmt" - "io" - "os" - "time" -) - -// RecordTrace outputs the request trace as text. -func RecordTrace(w io.Writer, trace *RequestTrace) { - attempt := AttemptReport{ - Reused: trace.Reused, - Latency: trace.Finish.Sub(trace.Start), - ReqWritten: trace.RequestWritten.Sub(trace.Start), - } - - if !trace.FirstResponseByte.IsZero() { - attempt.RespFirstByte = trace.FirstResponseByte.Sub(trace.Start) - attempt.WaitRespFirstByte = trace.FirstResponseByte.Sub(trace.RequestWritten) - } - - if !trace.Reused { - attempt.DNSStart = trace.DNSStart.Sub(trace.Start) - attempt.DNSDone = trace.DNSDone.Sub(trace.Start) - attempt.DNS = trace.DNSDone.Sub(trace.DNSStart) - - attempt.ConnectStart = trace.ConnectStart.Sub(trace.Start) - attempt.ConnectDone = trace.ConnectDone.Sub(trace.Start) - attempt.Connect = trace.ConnectDone.Sub(trace.ConnectStart) - - attempt.TLSHandshakeStart = trace.TLSHandshakeStart.Sub(trace.Start) - attempt.TLSHandshakeDone = trace.TLSHandshakeDone.Sub(trace.Start) - attempt.TLSHandshake = trace.TLSHandshakeDone.Sub(trace.TLSHandshakeStart) - } - - _, err := fmt.Fprintln(w, - "Latency:", - attempt.Latency, - - "ConnectionReused:", - fmt.Sprintf("%t", attempt.Reused), - - "DNSStartAt:", - fmt.Sprintf("%s", attempt.DNSStart), - "DNSDoneAt:", - fmt.Sprintf("%s", attempt.DNSDone), - "DNSDur:", - fmt.Sprintf("%s", attempt.DNS), - - "ConnectStartAt:", - fmt.Sprintf("%s", attempt.ConnectStart), - "ConnectDoneAt:", - fmt.Sprintf("%s", attempt.ConnectDone), - "ConnectDur:", - fmt.Sprintf("%s", attempt.Connect), - - "TLSStatAt:", - fmt.Sprintf("%s", attempt.TLSHandshakeStart), - "TLSDoneAt:", - fmt.Sprintf("%s", attempt.TLSHandshakeDone), - "TLSDur:", - fmt.Sprintf("%s", attempt.TLSHandshake), - - "RequestWritten", - fmt.Sprintf("%s", attempt.ReqWritten), - "RespFirstByte:", - fmt.Sprintf("%s", attempt.RespFirstByte), - "WaitRespFirstByte:", - fmt.Sprintf("%s", attempt.WaitRespFirstByte), - ) - if err != nil { - fmt.Fprintf(os.Stderr, "failed to write request trace, %v\n", err) - } -} - -// AttemptReport proviedes the structured timing information. -type AttemptReport struct { - Latency time.Duration - Reused bool - Err error - - DNSStart time.Duration - DNSDone time.Duration - DNS time.Duration - - ConnectStart time.Duration - ConnectDone time.Duration - Connect time.Duration - - TLSHandshakeStart time.Duration - TLSHandshakeDone time.Duration - TLSHandshake time.Duration - - ReqWritten time.Duration - RespFirstByte time.Duration - WaitRespFirstByte time.Duration -} diff --git a/example/aws/request/httptrace/main.go b/example/aws/request/httptrace/main.go index 88db88cd046..315cef1a404 100644 --- a/example/aws/request/httptrace/main.go +++ b/example/aws/request/httptrace/main.go @@ -8,6 +8,7 @@ import ( "errors" "flag" "fmt" + "log" "os" "github.com/aws/aws-sdk-go/aws" @@ -38,10 +39,6 @@ func main() { httpClient := NewClient(clientCfg) sess, err := session.NewSession(&aws.Config{ HTTPClient: httpClient, - - // Disable Retries to prevent the httptrace's getting mixed up on - // retries. - MaxRetries: aws.Int(0), }) if err != nil { exitErrorf(err, "failed to load config") @@ -60,7 +57,7 @@ func main() { if err != nil { fmt.Fprintf(os.Stderr, "failed to publish message, %v", err) } - RecordTrace(os.Stdout, trace) + log.Println(trace) fmt.Println() fmt.Printf("Message: ") @@ -73,18 +70,17 @@ func main() { // publishMessage will send the message to the SNS topic returning an request // trace for metrics. func publishMessage(ctx context.Context, svc *sns.SNS, topic, msg string) (*RequestTrace, error) { - traceCtx := NewRequestTrace(ctx) - defer traceCtx.RequestDone() + trace := &RequestTrace{} - _, err := svc.PublishWithContext(traceCtx, &sns.PublishInput{ + _, err := svc.PublishWithContext(ctx, &sns.PublishInput{ TopicArn: &topic, Message: &msg, - }) + }, trace.TraceRequest) if err != nil { return nil, err } - return traceCtx, nil + return trace, nil } func exitErrorf(err error, msg string, args ...interface{}) { diff --git a/example/aws/request/httptrace/trace.go b/example/aws/request/httptrace/trace.go index 8bb8f811c61..98f4cd191b5 100644 --- a/example/aws/request/httptrace/trace.go +++ b/example/aws/request/httptrace/trace.go @@ -1,95 +1,420 @@ package main import ( + "bytes" "context" "crypto/tls" + "fmt" + "io" + "io/ioutil" "net/http/httptrace" + "strings" "time" + + "github.com/aws/aws-sdk-go/aws/request" ) -// RequestTrace provides the trace time stamps of the HTTP request's segments. +// RequestLatency provides latencies for the SDK API request and its attempts. +type RequestLatency struct { + Latency time.Duration + Validate time.Duration + Build time.Duration + + Attempts []RequestAttemptLatency +} + +// RequestAttemptLatency provides latencies for an individual request attempt. +type RequestAttemptLatency struct { + Latency time.Duration + Err error + + Sign time.Duration + Send time.Duration + + HTTP HTTPLatency + + Unmarshal time.Duration + UnmarshalError time.Duration + + WillRetry bool + Retry time.Duration +} + +// HTTPLatency provides latencies for an HTTP request. +type HTTPLatency struct { + Latency time.Duration + ConnReused bool + + GetConn time.Duration + + DNS time.Duration + Connect time.Duration + TLS time.Duration + + WriteHeader time.Duration + WriteRequest time.Duration + WaitResponseFirstByte time.Duration + ReadHeader time.Duration + ReadBody time.Duration +} + +// RequestTrace provides the strucutre to store SDK request attempt latencies. +// Use TraceRequest as a API operation request option to capture trace metrics +// for the individual request. type RequestTrace struct { + Start, Finish time.Time + + ValidateStart, ValidateDone time.Time + BuildStart, BuildDone time.Time + + ReadResponseBody bool + + Attempts []*RequestAttemptTrace +} + +// Latency returns the latencies of the request trace components. +func (t RequestTrace) Latency() RequestLatency { + var attempts []RequestAttemptLatency + for _, a := range t.Attempts { + attempts = append(attempts, a.Latency()) + } + + latency := RequestLatency{ + Latency: safeTimeDelta(t.Start, t.Finish), + Validate: safeTimeDelta(t.ValidateStart, t.ValidateDone), + Build: safeTimeDelta(t.BuildStart, t.BuildDone), + Attempts: attempts, + } + + return latency +} + +// TraceRequest is a SDK request Option that will add request handlers to an +// individual request to track request latencies per attempt. Must be used only +// for a single request call per RequestTrace value. +func (t *RequestTrace) TraceRequest(r *request.Request) { + t.Start = time.Now() + r.Handlers.Complete.PushBack(t.onComplete) + + r.Handlers.Validate.PushFront(t.onValidateStart) + r.Handlers.Validate.PushBack(t.onValidateDone) + + r.Handlers.Build.PushFront(t.onBuildStart) + r.Handlers.Build.PushBack(t.onBuildDone) + + var attempt *RequestAttemptTrace + + // Signing and Start attempt + r.Handlers.Sign.PushFront(func(rr *request.Request) { + attempt = &RequestAttemptTrace{Start: time.Now()} + attempt.SignStart = attempt.Start + }) + r.Handlers.Sign.PushBack(func(rr *request.Request) { + attempt.SignDone = time.Now() + }) + + // Send + r.Handlers.Send.PushFront(func(rr *request.Request) { + attempt.SendStart = time.Now() + attempt.HTTPTrace = NewHTTPTrace(rr.Context()) + rr.SetContext(attempt.HTTPTrace) + }) + r.Handlers.Send.PushBack(func(rr *request.Request) { + attempt.SendDone = time.Now() + defer func() { + attempt.HTTPTrace.Finish = time.Now() + }() + + if rr.Error != nil { + return + } + + attempt.HTTPTrace.ReadHeaderDone = time.Now() + if t.ReadResponseBody { + attempt.HTTPTrace.ReadBodyStart = time.Now() + var w bytes.Buffer + if _, err := io.Copy(&w, rr.HTTPResponse.Body); err != nil { + rr.Error = err + return + } + rr.HTTPResponse.Body.Close() + rr.HTTPResponse.Body = ioutil.NopCloser(&w) + + attempt.HTTPTrace.ReadBodyDone = time.Now() + } + }) + + // Unmarshal + r.Handlers.Unmarshal.PushFront(func(rr *request.Request) { + attempt.UnmarshalStart = time.Now() + }) + r.Handlers.Unmarshal.PushBack(func(rr *request.Request) { + attempt.UnmarshalDone = time.Now() + }) + + // Unmarshal Error + r.Handlers.UnmarshalError.PushFront(func(rr *request.Request) { + attempt.UnmarshalErrorStart = time.Now() + }) + r.Handlers.UnmarshalError.PushBack(func(rr *request.Request) { + attempt.UnmarshalErrorDone = time.Now() + }) + + // Retry handling and delay + r.Handlers.Retry.PushFront(func(rr *request.Request) { + attempt.RetryStart = time.Now() + attempt.Err = rr.Error + }) + r.Handlers.AfterRetry.PushBack(func(rr *request.Request) { + attempt.RetryDone = time.Now() + attempt.WillRetry = rr.WillRetry() + }) + + // Complete Attempt + r.Handlers.CompleteAttempt.PushBack(func(rr *request.Request) { + attempt.Finish = time.Now() + t.Attempts = append(t.Attempts, attempt) + }) +} + +func (t *RequestTrace) String() string { + var w strings.Builder + + l := t.Latency() + writeDurField(&w, "Latency", l.Latency) + writeDurField(&w, "Validate", l.Validate) + writeDurField(&w, "Build", l.Build) + writeField(&w, "Attempts", "%d", len(t.Attempts)) + + for i, a := range t.Attempts { + fmt.Fprintf(&w, "\n\tAttempt: %d, %s", i, a) + } + + return w.String() +} + +func (t *RequestTrace) onComplete(*request.Request) { + t.Finish = time.Now() +} +func (t *RequestTrace) onValidateStart(*request.Request) { t.ValidateStart = time.Now() } +func (t *RequestTrace) onValidateDone(*request.Request) { t.ValidateDone = time.Now() } +func (t *RequestTrace) onBuildStart(*request.Request) { t.BuildStart = time.Now() } +func (t *RequestTrace) onBuildDone(*request.Request) { t.BuildDone = time.Now() } + +// RequestAttemptTrace provides a structure for storing trace information on +// the SDK's request attempt. +type RequestAttemptTrace struct { + Start, Finish time.Time + Err error + + SignStart, SignDone time.Time + + SendStart, SendDone time.Time + HTTPTrace *HTTPTrace + + UnmarshalStart, UnmarshalDone time.Time + UnmarshalErrorStart, UnmarshalErrorDone time.Time + + WillRetry bool + RetryStart, RetryDone time.Time +} + +// Latency returns the latencies of the request attempt trace components. +func (t *RequestAttemptTrace) Latency() RequestAttemptLatency { + return RequestAttemptLatency{ + Latency: safeTimeDelta(t.Start, t.Finish), + Err: t.Err, + + Sign: safeTimeDelta(t.SignStart, t.SignDone), + Send: safeTimeDelta(t.SendStart, t.SendDone), + + HTTP: t.HTTPTrace.Latency(), + + Unmarshal: safeTimeDelta(t.UnmarshalStart, t.UnmarshalDone), + UnmarshalError: safeTimeDelta(t.UnmarshalErrorStart, t.UnmarshalErrorDone), + + WillRetry: t.WillRetry, + Retry: safeTimeDelta(t.RetryStart, t.RetryDone), + } +} + +func (t *RequestAttemptTrace) String() string { + var w strings.Builder + + l := t.Latency() + writeDurField(&w, "Latency", l.Latency) + writeDurField(&w, "Sign", l.Sign) + writeDurField(&w, "Send", l.Send) + + writeDurField(&w, "Unmarshal", l.Unmarshal) + writeDurField(&w, "UnmarshalError", l.UnmarshalError) + + writeField(&w, "WillRetry", "%t", l.WillRetry) + writeDurField(&w, "Retry", l.Retry) + + fmt.Fprintf(&w, "\n\t\tHTTP: %s", t.HTTPTrace) + if t.Err != nil { + fmt.Fprintf(&w, "\n\t\tError: %v", t.Err) + } + + return w.String() +} + +// HTTPTrace provides the trace time stamps of the HTTP request's segments. +type HTTPTrace struct { context.Context Start, Finish time.Time - Reused bool + GetConnStart, GetConnDone time.Time + Reused bool DNSStart, DNSDone time.Time ConnectStart, ConnectDone time.Time TLSHandshakeStart, TLSHandshakeDone time.Time - RequestWritten time.Time + WriteHeaderDone time.Time + WriteRequestDone time.Time FirstResponseByte time.Time + + ReadHeaderStart, ReadHeaderDone time.Time + ReadBodyStart, ReadBodyDone time.Time } -// NewRequestTrace returns a initialized RequestTrace for an +// NewHTTPTrace returns a initialized HTTPTrace for an // httptrace.ClientTrace, based on the context passed. -func NewRequestTrace(ctx context.Context) *RequestTrace { - rt := &RequestTrace{ +func NewHTTPTrace(ctx context.Context) *HTTPTrace { + t := &HTTPTrace{ Start: time.Now(), } trace := &httptrace.ClientTrace{ - GetConn: rt.getConn, - GotConn: rt.gotConn, - PutIdleConn: rt.putIdleConn, - GotFirstResponseByte: rt.gotFirstResponseByte, - Got100Continue: rt.got100Continue, - DNSStart: rt.dnsStart, - DNSDone: rt.dnsDone, - ConnectStart: rt.connectStart, - ConnectDone: rt.connectDone, - TLSHandshakeStart: rt.tlsHandshakeStart, - TLSHandshakeDone: rt.tlsHandshakeDone, - WroteHeaders: rt.wroteHeaders, - Wait100Continue: rt.wait100Continue, - WroteRequest: rt.wroteRequest, + GetConn: t.getConn, + GotConn: t.gotConn, + PutIdleConn: t.putIdleConn, + GotFirstResponseByte: t.gotFirstResponseByte, + Got100Continue: t.got100Continue, + DNSStart: t.dnsStart, + DNSDone: t.dnsDone, + ConnectStart: t.connectStart, + ConnectDone: t.connectDone, + TLSHandshakeStart: t.tlsHandshakeStart, + TLSHandshakeDone: t.tlsHandshakeDone, + WroteHeaders: t.wroteHeaders, + Wait100Continue: t.wait100Continue, + WroteRequest: t.wroteRequest, } - rt.Context = httptrace.WithClientTrace(ctx, trace) + t.Context = httptrace.WithClientTrace(ctx, trace) - return rt + return t } -// TotalLatency returns the total time the request took. -func (rt *RequestTrace) TotalLatency() time.Duration { - return rt.Finish.Sub(rt.Start) +// Latency returns the latencies for an HTTP request. +func (t *HTTPTrace) Latency() HTTPLatency { + latency := HTTPLatency{ + Latency: safeTimeDelta(t.Start, t.Finish), + ConnReused: t.Reused, + + WriteHeader: safeTimeDelta(t.GetConnDone, t.WriteHeaderDone), + WriteRequest: safeTimeDelta(t.GetConnDone, t.WriteRequestDone), + WaitResponseFirstByte: safeTimeDelta(t.WriteRequestDone, t.FirstResponseByte), + ReadHeader: safeTimeDelta(t.ReadHeaderStart, t.ReadHeaderDone), + ReadBody: safeTimeDelta(t.ReadBodyStart, t.ReadBodyDone), + } + + if !t.Reused { + latency.GetConn = safeTimeDelta(t.GetConnStart, t.GetConnDone) + latency.DNS = safeTimeDelta(t.DNSStart, t.DNSDone) + latency.Connect = safeTimeDelta(t.ConnectStart, t.ConnectDone) + latency.TLS = safeTimeDelta(t.TLSHandshakeStart, t.TLSHandshakeDone) + } else { + latency.GetConn = safeTimeDelta(t.Start, t.GetConnDone) + } + + return latency } -// RequestDone completes the request trace. -func (rt *RequestTrace) RequestDone() { - rt.Finish = time.Now() +func (t *HTTPTrace) String() string { + var w strings.Builder + + l := t.Latency() + writeDurField(&w, "Latency", l.Latency) + writeField(&w, "ConnReused", "%t", l.ConnReused) + writeDurField(&w, "GetConn", l.GetConn) + + writeDurField(&w, "WriteHeader", l.WriteHeader) + writeDurField(&w, "WriteRequest", l.WriteRequest) + writeDurField(&w, "WaitResponseFirstByte", l.WaitResponseFirstByte) + writeDurField(&w, "ReadHeader", l.ReadHeader) + writeDurField(&w, "ReadBody", l.ReadBody) + + if !t.Reused { + fmt.Fprintf(&w, "\n\t\t\tConn: ") + writeDurField(&w, "DNS", l.DNS) + writeDurField(&w, "Connect", l.Connect) + writeDurField(&w, "TLS", l.TLS) + } + + return w.String() } -func (rt *RequestTrace) getConn(hostPort string) {} -func (rt *RequestTrace) gotConn(info httptrace.GotConnInfo) { - rt.Reused = info.Reused +func (t *HTTPTrace) getConn(hostPort string) { + t.GetConnStart = time.Now() +} +func (t *HTTPTrace) gotConn(info httptrace.GotConnInfo) { + t.GetConnDone = time.Now() + t.Reused = info.Reused } -func (rt *RequestTrace) putIdleConn(err error) {} -func (rt *RequestTrace) gotFirstResponseByte() { - rt.FirstResponseByte = time.Now() +func (t *HTTPTrace) putIdleConn(err error) {} +func (t *HTTPTrace) gotFirstResponseByte() { + t.FirstResponseByte = time.Now() + t.ReadHeaderStart = t.FirstResponseByte } -func (rt *RequestTrace) got100Continue() {} -func (rt *RequestTrace) dnsStart(info httptrace.DNSStartInfo) { - rt.DNSStart = time.Now() +func (t *HTTPTrace) got100Continue() {} +func (t *HTTPTrace) dnsStart(info httptrace.DNSStartInfo) { + t.DNSStart = time.Now() } -func (rt *RequestTrace) dnsDone(info httptrace.DNSDoneInfo) { - rt.DNSDone = time.Now() +func (t *HTTPTrace) dnsDone(info httptrace.DNSDoneInfo) { + t.DNSDone = time.Now() } -func (rt *RequestTrace) connectStart(network, addr string) { - rt.ConnectStart = time.Now() +func (t *HTTPTrace) connectStart(network, addr string) { + t.ConnectStart = time.Now() } -func (rt *RequestTrace) connectDone(network, addr string, err error) { - rt.ConnectDone = time.Now() +func (t *HTTPTrace) connectDone(network, addr string, err error) { + t.ConnectDone = time.Now() } -func (rt *RequestTrace) tlsHandshakeStart() { - rt.TLSHandshakeStart = time.Now() +func (t *HTTPTrace) tlsHandshakeStart() { + t.TLSHandshakeStart = time.Now() } -func (rt *RequestTrace) tlsHandshakeDone(state tls.ConnectionState, err error) { - rt.TLSHandshakeDone = time.Now() +func (t *HTTPTrace) tlsHandshakeDone(state tls.ConnectionState, err error) { + t.TLSHandshakeDone = time.Now() } -func (rt *RequestTrace) wroteHeaders() {} -func (rt *RequestTrace) wait100Continue() {} -func (rt *RequestTrace) wroteRequest(info httptrace.WroteRequestInfo) { - rt.RequestWritten = time.Now() +func (t *HTTPTrace) wroteHeaders() { + t.WriteHeaderDone = time.Now() +} +func (t *HTTPTrace) wait100Continue() {} +func (t *HTTPTrace) wroteRequest(info httptrace.WroteRequestInfo) { + t.WriteRequestDone = time.Now() +} + +func safeTimeDelta(start, end time.Time) time.Duration { + if start.IsZero() || end.IsZero() { + return 0 + } + + return end.Sub(start) +} + +func writeField(w io.Writer, field string, format string, args ...interface{}) error { + _, err := fmt.Fprintf(w, "%s: "+format+", ", append([]interface{}{field}, args...)...) + return err +} + +func writeDurField(w io.Writer, field string, dur time.Duration) error { + if dur == 0 { + return nil + } + + _, err := fmt.Fprintf(w, "%s: %s, ", field, dur) + return err }