From 0d7bf36aa5ecbf2030e780220929e5a634db029f Mon Sep 17 00:00:00 2001 From: Jason Del Ponte Date: Tue, 21 Jul 2020 14:20:04 -0700 Subject: [PATCH 1/6] example/aws/request/httptrace: Update example with more metrics 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 14:21:23 Latency: 292.687003ms, Validate: 23.261µs, Build: 92.249µs, Attempts: 1, Attempt: 0, Latency: 292.541266ms, Sign: 159.755µs, Send: 292.173529ms, Unmarshal: 203.204µs, WillRetry: false, HTTP: Latency: 292.174168ms, ConnReused: false, GetConn: 238.080409ms, DNS: 22.774015ms, Connect: 22.774015ms, TLS: 200.809752ms, WriteRequest: 424.376µs, WaitResponseFirstByte: 292.058664ms, ReadResponseHeader: 115.196µs, Connection re-used: 2020/07/21 14:21:29 Latency: 47.824618ms, Validate: 2.91µs, Build: 110.86µs, Attempts: 1, Attempt: 0, Latency: 47.68784ms, Sign: 237.076µs, Send: 47.29333ms, Unmarshal: 151.831µs, WillRetry: false, HTTP: Latency: 47.29391ms, ConnReused: true, WriteRequest: 285.042µs, WaitResponseFirstByte: 47.233202ms, ReadResponseHeader: 60.252µs, --- 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 | 317 ++++++++++++++++++++---- 4 files changed, 291 insertions(+), 166 deletions(-) delete mode 100644 example/aws/request/httptrace/logger.go diff --git a/example/aws/request/httptrace/README.md b/example/aws/request/httptrace/README.md index 22bd428b02..451efc8b42 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 +Message: first message +2020/07/21 14:21:23 Latency: 292.687003ms, Validate: 23.261µs, Build: 92.249µs, Attempts: 1, + Attempt: 0, Latency: 292.541266ms, Sign: 159.755µs, Send: 292.173529ms, Unmarshal: 203.204µs, WillRetry: false, + HTTP: Latency: 292.174168ms, ConnReused: false, GetConn: 238.080409ms, DNS: 22.774015ms, Connect: 22.774015ms, TLS: 200.809752ms, WriteRequest: 424.376µs, WaitResponseFirstByte: 292.058664ms, ReadResponseHeader: 115.196µs, + +Message: second message +2020/07/21 14:21:29 Latency: 47.824618ms, Validate: 2.91µs, Build: 110.86µs, Attempts: 1, + Attempt: 0, Latency: 47.68784ms, Sign: 237.076µs, Send: 47.29333ms, Unmarshal: 151.831µs, WillRetry: false, + HTTP: Latency: 47.29391ms, ConnReused: true, WriteRequest: 285.042µs, WaitResponseFirstByte: 47.233202ms, ReadResponseHeader: 60.252µs, + +Message: third message +2020/07/21 14:21:33 Latency: 31.435353ms, Validate: 1.603µs, Build: 29.356µs, Attempts: 1, + Attempt: 0, Latency: 31.39293ms, Sign: 63.152µs, Send: 31.245591ms, Unmarshal: 81.123µs, WillRetry: false, + HTTP: Latency: 31.24588ms, ConnReused: true, WriteRequest: 151.738µs, WaitResponseFirstByte: 31.208877ms, ReadResponseHeader: 36.731µs, + +Message: last message +2020/07/21 14:21:37 Latency: 42.643276ms, Validate: 1.903µs, Build: 33.829µs, Attempts: 1, + Attempt: 0, Latency: 42.582587ms, Sign: 57.561µs, Send: 42.264062ms, Unmarshal: 246.32µs, WillRetry: false, + HTTP: Latency: 42.265295ms, ConnReused: true, WriteRequest: 178.259µs, WaitResponseFirstByte: 42.142391ms, ReadResponseHeader: 122.393µs, ``` + diff --git a/example/aws/request/httptrace/logger.go b/example/aws/request/httptrace/logger.go deleted file mode 100644 index bbab5ec98f..0000000000 --- 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 88db88cd04..315cef1a40 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 8bb8f811c6..bc3f0101c7 100644 --- a/example/aws/request/httptrace/trace.go +++ b/example/aws/request/httptrace/trace.go @@ -1,95 +1,308 @@ 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. +// 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 + + SDKValidateStart, SDKValidateDone time.Time + SDKBuildStart, SDKBuildDone time.Time + + ReadResponseBody bool + + Attempts []*RequestAttemptTrace +} + +// 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.SDKSignStart = attempt.Start + }) + r.Handlers.Sign.PushBack(func(rr *request.Request) { + attempt.SDKSignDone = time.Now() + }) + + // Send + r.Handlers.Send.PushFront(func(rr *request.Request) { + attempt.SDKSendStart = time.Now() + attempt.HTTPTrace = NewHTTPTrace(rr.Context()) + rr.SetContext(attempt.HTTPTrace) + }) + r.Handlers.Send.PushBack(func(rr *request.Request) { + attempt.SDKSendDone = 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.SDKUnmarshalStart = time.Now() + }) + r.Handlers.Unmarshal.PushBack(func(rr *request.Request) { + attempt.SDKUnmarshalDone = time.Now() + }) + + // Unmarshal Error + r.Handlers.UnmarshalError.PushFront(func(rr *request.Request) { + attempt.SDKUnmarshalErrorStart = time.Now() + }) + r.Handlers.UnmarshalError.PushBack(func(rr *request.Request) { + attempt.SDKUnmarshalErrorDone = time.Now() + }) + + // Retry handling and delay + r.Handlers.Retry.PushFront(func(rr *request.Request) { + attempt.SDKRetryStart = time.Now() + attempt.Err = rr.Error + }) + r.Handlers.AfterRetry.PushBack(func(rr *request.Request) { + attempt.SDKRetryDone = 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 + + writeDurField(&w, "Latency", t.Start, t.Finish) + writeDurField(&w, "Validate", t.SDKValidateStart, t.SDKValidateDone) + writeDurField(&w, "Build", t.SDKBuildStart, t.SDKBuildDone) + 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.SDKValidateStart = time.Now() } +func (t *RequestTrace) onValidateDone(*request.Request) { t.SDKValidateDone = time.Now() } +func (t *RequestTrace) onBuildStart(*request.Request) { t.SDKBuildStart = time.Now() } +func (t *RequestTrace) onBuildDone(*request.Request) { t.SDKBuildDone = 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 + + SDKSignStart, SDKSignDone time.Time + + SDKSendStart, SDKSendDone time.Time + HTTPTrace *HTTPTrace + + SDKUnmarshalStart, SDKUnmarshalDone time.Time + SDKUnmarshalErrorStart, SDKUnmarshalErrorDone time.Time + + WillRetry bool + SDKRetryStart, SDKRetryDone time.Time +} + +func (at *RequestAttemptTrace) String() string { + var w strings.Builder + + writeDurField(&w, "Latency", at.Start, at.Finish) + writeDurField(&w, "Sign", at.SDKSignStart, at.SDKSignDone) + writeDurField(&w, "Send", at.SDKSendStart, at.SDKSendDone) + + writeDurField(&w, "Unmarshal", at.SDKUnmarshalStart, at.SDKUnmarshalDone) + writeDurField(&w, "UnmarshalError", at.SDKUnmarshalErrorStart, at.SDKUnmarshalErrorDone) + + writeField(&w, "WillRetry", "%t", at.WillRetry) + writeDurField(&w, "Retry", at.SDKRetryStart, at.SDKRetryDone) + + fmt.Fprintf(&w, "\n\t\tHTTP: %s", at.HTTPTrace) + if at.Err != nil { + fmt.Fprintf(&w, "\n\t\tError: %v", at.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) -} +func (t *HTTPTrace) String() string { + var w strings.Builder -// RequestDone completes the request trace. -func (rt *RequestTrace) RequestDone() { - rt.Finish = time.Now() + writeDurField(&w, "Latency", t.Start, t.Finish) + writeField(&w, "ConnReused", "%t", t.Reused) + + if !t.Reused { + writeDurField(&w, "GetConn", t.GetConnStart, t.GetConnDone) + + //writeDurField(&w, "DNSStart", t.Start, t.DNSStart) + writeDurField(&w, "DNS", t.DNSStart, t.DNSDone) + + //writeDurField(&w, "ConnectStart", t.Start, t.DNSStart) + writeDurField(&w, "Connect", t.DNSStart, t.DNSDone) + + //writeDurField(&w, "TLSHandshakeStart", t.Start, t.TLSHandshakeStart) + writeDurField(&w, "TLS", t.TLSHandshakeStart, t.TLSHandshakeDone) + } + + writeDurField(&w, "WriteRequest", t.GetConnDone, t.WriteRequestDone) + writeDurField(&w, "WaitResponseFirstByte", t.Start, t.FirstResponseByte) + writeDurField(&w, "ReadResponseHeader", t.ReadHeaderStart, t.ReadHeaderDone) + writeDurField(&w, "ReadResponseBody", t.ReadBodyStart, t.ReadBodyDone) + + 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 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, start, stop time.Time) error { + if start.IsZero() || stop.IsZero() { + return nil + } + + _, err := fmt.Fprintf(w, "%s: %s, ", field, stop.Sub(start)) + return err } From 271b60ee64b3e63d5d083e01e8a736ac83718bcc Mon Sep 17 00:00:00 2001 From: Jason Del Ponte Date: Tue, 21 Jul 2020 15:29:28 -0700 Subject: [PATCH 2/6] add GetConn metric for reused connections --- example/aws/request/httptrace/README.md | 37 ++++++++++++------------- example/aws/request/httptrace/trace.go | 2 ++ 2 files changed, 20 insertions(+), 19 deletions(-) diff --git a/example/aws/request/httptrace/README.md b/example/aws/request/httptrace/README.md index 451efc8b42..6b3d5f3c29 100644 --- a/example/aws/request/httptrace/README.md +++ b/example/aws/request/httptrace/README.md @@ -33,24 +33,23 @@ Message: My Really cool Message The example will output the http trace timing information for how long the request took. ``` -Message: first message -2020/07/21 14:21:23 Latency: 292.687003ms, Validate: 23.261µs, Build: 92.249µs, Attempts: 1, - Attempt: 0, Latency: 292.541266ms, Sign: 159.755µs, Send: 292.173529ms, Unmarshal: 203.204µs, WillRetry: false, - HTTP: Latency: 292.174168ms, ConnReused: false, GetConn: 238.080409ms, DNS: 22.774015ms, Connect: 22.774015ms, TLS: 200.809752ms, WriteRequest: 424.376µs, WaitResponseFirstByte: 292.058664ms, ReadResponseHeader: 115.196µs, - -Message: second message -2020/07/21 14:21:29 Latency: 47.824618ms, Validate: 2.91µs, Build: 110.86µs, Attempts: 1, - Attempt: 0, Latency: 47.68784ms, Sign: 237.076µs, Send: 47.29333ms, Unmarshal: 151.831µs, WillRetry: false, - HTTP: Latency: 47.29391ms, ConnReused: true, WriteRequest: 285.042µs, WaitResponseFirstByte: 47.233202ms, ReadResponseHeader: 60.252µs, - -Message: third message -2020/07/21 14:21:33 Latency: 31.435353ms, Validate: 1.603µs, Build: 29.356µs, Attempts: 1, - Attempt: 0, Latency: 31.39293ms, Sign: 63.152µs, Send: 31.245591ms, Unmarshal: 81.123µs, WillRetry: false, - HTTP: Latency: 31.24588ms, ConnReused: true, WriteRequest: 151.738µs, WaitResponseFirstByte: 31.208877ms, ReadResponseHeader: 36.731µs, - -Message: last message -2020/07/21 14:21:37 Latency: 42.643276ms, Validate: 1.903µs, Build: 33.829µs, Attempts: 1, - Attempt: 0, Latency: 42.582587ms, Sign: 57.561µs, Send: 42.264062ms, Unmarshal: 246.32µs, WillRetry: false, - HTTP: Latency: 42.265295ms, ConnReused: true, WriteRequest: 178.259µs, WaitResponseFirstByte: 42.142391ms, ReadResponseHeader: 122.393µs, +2020/07/21 15:28:13 Latency: 290.859243ms, Validate: 20.607µs, Build: 114.17µs, Attempts: 1, + Attempt: 0, Latency: 290.691814ms, Sign: 174.017µs, Send: 290.303676ms, Unmarshal: 196.662µs, WillRetry: false, + HTTP: Latency: 290.304018ms, ConnReused: false, GetConn: 239.350422ms, DNS: 40.48639ms, Connect: 40.48639ms, TLS: 184.738452ms, WriteRequest: 310.311µs, WaitResponseFirstByte: 290.25327ms, ReadResponseHeader: 50.392µs, + +Message: second +2020/07/21 15:28:15 Latency: 34.778924ms, Validate: 3.231µs, Build: 66.932µs, Attempts: 1, + Attempt: 0, Latency: 34.685914ms, Sign: 92.238µs, Send: 33.879391ms, Unmarshal: 698.703µs, WillRetry: false, + HTTP: Latency: 33.880956ms, ConnReused: true, GetConn: 29.447µs, WriteRequest: 151.002µs, WaitResponseFirstByte: 33.307018ms, ReadResponseHeader: 572.807µs, + +Message: thrid +2020/07/21 15:28:16 Latency: 35.49632ms, Validate: 1.391µs, Build: 30.989µs, Attempts: 1, + Attempt: 0, Latency: 35.446929ms, Sign: 59.237µs, Send: 35.218487ms, Unmarshal: 164.304µs, WillRetry: false, + HTTP: Latency: 35.219014ms, ConnReused: true, GetConn: 36.817µs, WriteRequest: 160.361µs, WaitResponseFirstByte: 35.170978ms, ReadResponseHeader: 47.592µs, + +Message: fourth +2020/07/21 15:28:21 Latency: 39.099871ms, Validate: 1.613µs, Build: 33.838µs, Attempts: 1, + Attempt: 0, Latency: 39.037477ms, Sign: 59.805µs, Send: 38.84714ms, Unmarshal: 125.874µs, WillRetry: false, + HTTP: Latency: 38.847806ms, ConnReused: true, GetConn: 47.417µs, WriteRequest: 224.433µs, WaitResponseFirstByte: 38.803854ms, ReadResponseHeader: 43.478µs, ``` diff --git a/example/aws/request/httptrace/trace.go b/example/aws/request/httptrace/trace.go index bc3f0101c7..d2d7c7bc29 100644 --- a/example/aws/request/httptrace/trace.go +++ b/example/aws/request/httptrace/trace.go @@ -244,6 +244,8 @@ func (t *HTTPTrace) String() string { //writeDurField(&w, "TLSHandshakeStart", t.Start, t.TLSHandshakeStart) writeDurField(&w, "TLS", t.TLSHandshakeStart, t.TLSHandshakeDone) + } else { + writeDurField(&w, "GetConn", t.Start, t.GetConnDone) } writeDurField(&w, "WriteRequest", t.GetConnDone, t.WriteRequestDone) From 2b821cccabe8f560195f2218a2c02bd957357931 Mon Sep 17 00:00:00 2001 From: Jason Del Ponte Date: Tue, 21 Jul 2020 15:40:04 -0700 Subject: [PATCH 3/6] fix metric output cleanup comments --- example/aws/request/httptrace/README.md | 24 ++++++++++++------------ example/aws/request/httptrace/trace.go | 8 +------- 2 files changed, 13 insertions(+), 19 deletions(-) diff --git a/example/aws/request/httptrace/README.md b/example/aws/request/httptrace/README.md index 6b3d5f3c29..de90bbf2d7 100644 --- a/example/aws/request/httptrace/README.md +++ b/example/aws/request/httptrace/README.md @@ -33,23 +33,23 @@ Message: My Really cool Message The example will output the http trace timing information for how long the request took. ``` -2020/07/21 15:28:13 Latency: 290.859243ms, Validate: 20.607µs, Build: 114.17µs, Attempts: 1, - Attempt: 0, Latency: 290.691814ms, Sign: 174.017µs, Send: 290.303676ms, Unmarshal: 196.662µs, WillRetry: false, - HTTP: Latency: 290.304018ms, ConnReused: false, GetConn: 239.350422ms, DNS: 40.48639ms, Connect: 40.48639ms, TLS: 184.738452ms, WriteRequest: 310.311µs, WaitResponseFirstByte: 290.25327ms, ReadResponseHeader: 50.392µs, +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, DNS: 20.385136ms, Connect: 14.947772ms, TLS: 189.910822ms, WriteRequest: 325.956µs, WaitResponseFirstByte: 277.509316ms, ReadResponseHeader: 71.234µs, Message: second -2020/07/21 15:28:15 Latency: 34.778924ms, Validate: 3.231µs, Build: 66.932µs, Attempts: 1, - Attempt: 0, Latency: 34.685914ms, Sign: 92.238µs, Send: 33.879391ms, Unmarshal: 698.703µs, WillRetry: false, - HTTP: Latency: 33.880956ms, ConnReused: true, GetConn: 29.447µs, WriteRequest: 151.002µs, WaitResponseFirstByte: 33.307018ms, ReadResponseHeader: 572.807µs, +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:28:16 Latency: 35.49632ms, Validate: 1.391µs, Build: 30.989µs, Attempts: 1, - Attempt: 0, Latency: 35.446929ms, Sign: 59.237µs, Send: 35.218487ms, Unmarshal: 164.304µs, WillRetry: false, - HTTP: Latency: 35.219014ms, ConnReused: true, GetConn: 36.817µs, WriteRequest: 160.361µs, WaitResponseFirstByte: 35.170978ms, ReadResponseHeader: 47.592µs, +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:28:21 Latency: 39.099871ms, Validate: 1.613µs, Build: 33.838µs, Attempts: 1, - Attempt: 0, Latency: 39.037477ms, Sign: 59.805µs, Send: 38.84714ms, Unmarshal: 125.874µs, WillRetry: false, - HTTP: Latency: 38.847806ms, ConnReused: true, GetConn: 47.417µs, WriteRequest: 224.433µs, WaitResponseFirstByte: 38.803854ms, ReadResponseHeader: 43.478µs, +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/trace.go b/example/aws/request/httptrace/trace.go index d2d7c7bc29..9c264c8bab 100644 --- a/example/aws/request/httptrace/trace.go +++ b/example/aws/request/httptrace/trace.go @@ -235,14 +235,8 @@ func (t *HTTPTrace) String() string { if !t.Reused { writeDurField(&w, "GetConn", t.GetConnStart, t.GetConnDone) - - //writeDurField(&w, "DNSStart", t.Start, t.DNSStart) writeDurField(&w, "DNS", t.DNSStart, t.DNSDone) - - //writeDurField(&w, "ConnectStart", t.Start, t.DNSStart) - writeDurField(&w, "Connect", t.DNSStart, t.DNSDone) - - //writeDurField(&w, "TLSHandshakeStart", t.Start, t.TLSHandshakeStart) + writeDurField(&w, "Connect", t.ConnectStart, t.ConnectDone) writeDurField(&w, "TLS", t.TLSHandshakeStart, t.TLSHandshakeDone) } else { writeDurField(&w, "GetConn", t.Start, t.GetConnDone) From d41ff622adc8922216fcec3276de4f5d6dd3e54e Mon Sep 17 00:00:00 2001 From: Jason Del Ponte Date: Tue, 21 Jul 2020 15:53:57 -0700 Subject: [PATCH 4/6] move Conn to its on line --- example/aws/request/httptrace/README.md | 3 ++- example/aws/request/httptrace/trace.go | 10 +++++++--- 2 files changed, 9 insertions(+), 4 deletions(-) diff --git a/example/aws/request/httptrace/README.md b/example/aws/request/httptrace/README.md index de90bbf2d7..55e72b8c1a 100644 --- a/example/aws/request/httptrace/README.md +++ b/example/aws/request/httptrace/README.md @@ -35,7 +35,8 @@ The example will output the http trace timing information for how long the reque ``` 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, DNS: 20.385136ms, Connect: 14.947772ms, TLS: 189.910822ms, WriteRequest: 325.956µs, WaitResponseFirstByte: 277.509316ms, ReadResponseHeader: 71.234µs, + 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, diff --git a/example/aws/request/httptrace/trace.go b/example/aws/request/httptrace/trace.go index 9c264c8bab..0298128109 100644 --- a/example/aws/request/httptrace/trace.go +++ b/example/aws/request/httptrace/trace.go @@ -235,9 +235,6 @@ func (t *HTTPTrace) String() string { if !t.Reused { writeDurField(&w, "GetConn", t.GetConnStart, t.GetConnDone) - writeDurField(&w, "DNS", t.DNSStart, t.DNSDone) - writeDurField(&w, "Connect", t.ConnectStart, t.ConnectDone) - writeDurField(&w, "TLS", t.TLSHandshakeStart, t.TLSHandshakeDone) } else { writeDurField(&w, "GetConn", t.Start, t.GetConnDone) } @@ -247,6 +244,13 @@ func (t *HTTPTrace) String() string { writeDurField(&w, "ReadResponseHeader", t.ReadHeaderStart, t.ReadHeaderDone) writeDurField(&w, "ReadResponseBody", t.ReadBodyStart, t.ReadBodyDone) + if !t.Reused { + fmt.Fprintf(&w, "\n\t\t\tConn: ") + writeDurField(&w, "DNS", t.DNSStart, t.DNSDone) + writeDurField(&w, "Connect", t.ConnectStart, t.ConnectDone) + writeDurField(&w, "TLS", t.TLSHandshakeStart, t.TLSHandshakeDone) + } + return w.String() } From eb6b81cfde8a57e7f7659b1f837b1227371bf809 Mon Sep 17 00:00:00 2001 From: Jason Del Ponte Date: Tue, 21 Jul 2020 16:59:31 -0700 Subject: [PATCH 5/6] migrate to latency exposed behavior --- example/aws/request/httptrace/trace.go | 220 +++++++++++++++++++------ 1 file changed, 166 insertions(+), 54 deletions(-) diff --git a/example/aws/request/httptrace/trace.go b/example/aws/request/httptrace/trace.go index 0298128109..98f4cd191b 100644 --- a/example/aws/request/httptrace/trace.go +++ b/example/aws/request/httptrace/trace.go @@ -14,20 +14,81 @@ import ( "github.com/aws/aws-sdk-go/aws/request" ) +// 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 - SDKValidateStart, SDKValidateDone time.Time - SDKBuildStart, SDKBuildDone 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. @@ -46,20 +107,20 @@ func (t *RequestTrace) TraceRequest(r *request.Request) { // Signing and Start attempt r.Handlers.Sign.PushFront(func(rr *request.Request) { attempt = &RequestAttemptTrace{Start: time.Now()} - attempt.SDKSignStart = attempt.Start + attempt.SignStart = attempt.Start }) r.Handlers.Sign.PushBack(func(rr *request.Request) { - attempt.SDKSignDone = time.Now() + attempt.SignDone = time.Now() }) // Send r.Handlers.Send.PushFront(func(rr *request.Request) { - attempt.SDKSendStart = time.Now() + attempt.SendStart = time.Now() attempt.HTTPTrace = NewHTTPTrace(rr.Context()) rr.SetContext(attempt.HTTPTrace) }) r.Handlers.Send.PushBack(func(rr *request.Request) { - attempt.SDKSendDone = time.Now() + attempt.SendDone = time.Now() defer func() { attempt.HTTPTrace.Finish = time.Now() }() @@ -85,27 +146,27 @@ func (t *RequestTrace) TraceRequest(r *request.Request) { // Unmarshal r.Handlers.Unmarshal.PushFront(func(rr *request.Request) { - attempt.SDKUnmarshalStart = time.Now() + attempt.UnmarshalStart = time.Now() }) r.Handlers.Unmarshal.PushBack(func(rr *request.Request) { - attempt.SDKUnmarshalDone = time.Now() + attempt.UnmarshalDone = time.Now() }) // Unmarshal Error r.Handlers.UnmarshalError.PushFront(func(rr *request.Request) { - attempt.SDKUnmarshalErrorStart = time.Now() + attempt.UnmarshalErrorStart = time.Now() }) r.Handlers.UnmarshalError.PushBack(func(rr *request.Request) { - attempt.SDKUnmarshalErrorDone = time.Now() + attempt.UnmarshalErrorDone = time.Now() }) // Retry handling and delay r.Handlers.Retry.PushFront(func(rr *request.Request) { - attempt.SDKRetryStart = time.Now() + attempt.RetryStart = time.Now() attempt.Err = rr.Error }) r.Handlers.AfterRetry.PushBack(func(rr *request.Request) { - attempt.SDKRetryDone = time.Now() + attempt.RetryDone = time.Now() attempt.WillRetry = rr.WillRetry() }) @@ -119,9 +180,10 @@ func (t *RequestTrace) TraceRequest(r *request.Request) { func (t *RequestTrace) String() string { var w strings.Builder - writeDurField(&w, "Latency", t.Start, t.Finish) - writeDurField(&w, "Validate", t.SDKValidateStart, t.SDKValidateDone) - writeDurField(&w, "Build", t.SDKBuildStart, t.SDKBuildDone) + 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 { @@ -134,10 +196,10 @@ func (t *RequestTrace) String() string { func (t *RequestTrace) onComplete(*request.Request) { t.Finish = time.Now() } -func (t *RequestTrace) onValidateStart(*request.Request) { t.SDKValidateStart = time.Now() } -func (t *RequestTrace) onValidateDone(*request.Request) { t.SDKValidateDone = time.Now() } -func (t *RequestTrace) onBuildStart(*request.Request) { t.SDKBuildStart = time.Now() } -func (t *RequestTrace) onBuildDone(*request.Request) { t.SDKBuildDone = 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. @@ -145,34 +207,54 @@ type RequestAttemptTrace struct { Start, Finish time.Time Err error - SDKSignStart, SDKSignDone time.Time + SignStart, SignDone time.Time - SDKSendStart, SDKSendDone time.Time - HTTPTrace *HTTPTrace + SendStart, SendDone time.Time + HTTPTrace *HTTPTrace - SDKUnmarshalStart, SDKUnmarshalDone time.Time - SDKUnmarshalErrorStart, SDKUnmarshalErrorDone time.Time + UnmarshalStart, UnmarshalDone time.Time + UnmarshalErrorStart, UnmarshalErrorDone time.Time - WillRetry bool - SDKRetryStart, SDKRetryDone time.Time + WillRetry bool + RetryStart, RetryDone time.Time } -func (at *RequestAttemptTrace) String() string { +// 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 - writeDurField(&w, "Latency", at.Start, at.Finish) - writeDurField(&w, "Sign", at.SDKSignStart, at.SDKSignDone) - writeDurField(&w, "Send", at.SDKSendStart, at.SDKSendDone) + l := t.Latency() + writeDurField(&w, "Latency", l.Latency) + writeDurField(&w, "Sign", l.Sign) + writeDurField(&w, "Send", l.Send) - writeDurField(&w, "Unmarshal", at.SDKUnmarshalStart, at.SDKUnmarshalDone) - writeDurField(&w, "UnmarshalError", at.SDKUnmarshalErrorStart, at.SDKUnmarshalErrorDone) + writeDurField(&w, "Unmarshal", l.Unmarshal) + writeDurField(&w, "UnmarshalError", l.UnmarshalError) - writeField(&w, "WillRetry", "%t", at.WillRetry) - writeDurField(&w, "Retry", at.SDKRetryStart, at.SDKRetryDone) + writeField(&w, "WillRetry", "%t", l.WillRetry) + writeDurField(&w, "Retry", l.Retry) - fmt.Fprintf(&w, "\n\t\tHTTP: %s", at.HTTPTrace) - if at.Err != nil { - fmt.Fprintf(&w, "\n\t\tError: %v", at.Err) + 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() @@ -227,28 +309,50 @@ func NewHTTPTrace(ctx context.Context) *HTTPTrace { return t } -func (t *HTTPTrace) String() string { - var w strings.Builder - - writeDurField(&w, "Latency", t.Start, t.Finish) - writeField(&w, "ConnReused", "%t", t.Reused) +// 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 { - writeDurField(&w, "GetConn", t.GetConnStart, t.GetConnDone) + 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 { - writeDurField(&w, "GetConn", t.Start, t.GetConnDone) + latency.GetConn = safeTimeDelta(t.Start, t.GetConnDone) } - writeDurField(&w, "WriteRequest", t.GetConnDone, t.WriteRequestDone) - writeDurField(&w, "WaitResponseFirstByte", t.Start, t.FirstResponseByte) - writeDurField(&w, "ReadResponseHeader", t.ReadHeaderStart, t.ReadHeaderDone) - writeDurField(&w, "ReadResponseBody", t.ReadBodyStart, t.ReadBodyDone) + return latency +} + +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", t.DNSStart, t.DNSDone) - writeDurField(&w, "Connect", t.ConnectStart, t.ConnectDone) - writeDurField(&w, "TLS", t.TLSHandshakeStart, t.TLSHandshakeDone) + writeDurField(&w, "DNS", l.DNS) + writeDurField(&w, "Connect", l.Connect) + writeDurField(&w, "TLS", l.TLS) } return w.String() @@ -293,16 +397,24 @@ 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, start, stop time.Time) error { - if start.IsZero() || stop.IsZero() { +func writeDurField(w io.Writer, field string, dur time.Duration) error { + if dur == 0 { return nil } - _, err := fmt.Fprintf(w, "%s: %s, ", field, stop.Sub(start)) + _, err := fmt.Fprintf(w, "%s: %s, ", field, dur) return err } From 03ead2c9899b6b8bb376d42d552b893ef9cc756d Mon Sep 17 00:00:00 2001 From: Jason Del Ponte Date: Tue, 21 Jul 2020 17:22:55 -0700 Subject: [PATCH 6/6] add changelog --- CHANGELOG_PENDING.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/CHANGELOG_PENDING.md b/CHANGELOG_PENDING.md index 8a1927a39c..1d65d7c80c 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