1// +build go1.13,integration,perftest
2
3package main
4
5import (
6	"context"
7	"crypto/tls"
8	"fmt"
9	"net/http/httptrace"
10	"strconv"
11	"strings"
12	"time"
13
14	"github.com/aws/aws-sdk-go/aws/request"
15)
16
17type RequestTrace struct {
18	Operation string
19	ID        string
20
21	context.Context
22
23	start, finish time.Time
24
25	errs       Errors
26	attempts   []RequestAttempt
27	curAttempt RequestAttempt
28}
29
30func NewRequestTrace(ctx context.Context, op, id string) *RequestTrace {
31	rt := &RequestTrace{
32		Operation: op,
33		ID:        id,
34		start:     time.Now(),
35		attempts:  []RequestAttempt{},
36		curAttempt: RequestAttempt{
37			ID: id,
38		},
39	}
40
41	trace := &httptrace.ClientTrace{
42		GetConn:              rt.getConn,
43		GotConn:              rt.gotConn,
44		PutIdleConn:          rt.putIdleConn,
45		GotFirstResponseByte: rt.gotFirstResponseByte,
46		Got100Continue:       rt.got100Continue,
47		DNSStart:             rt.dnsStart,
48		DNSDone:              rt.dnsDone,
49		ConnectStart:         rt.connectStart,
50		ConnectDone:          rt.connectDone,
51		TLSHandshakeStart:    rt.tlsHandshakeStart,
52		TLSHandshakeDone:     rt.tlsHandshakeDone,
53		WroteHeaders:         rt.wroteHeaders,
54		Wait100Continue:      rt.wait100Continue,
55		WroteRequest:         rt.wroteRequest,
56	}
57
58	rt.Context = httptrace.WithClientTrace(ctx, trace)
59
60	return rt
61}
62
63func (rt *RequestTrace) AppendError(err error) {
64	rt.errs = append(rt.errs, err)
65}
66func (rt *RequestTrace) OnSendAttempt(r *request.Request) {
67	rt.curAttempt.SendStart = time.Now()
68}
69func (rt *RequestTrace) OnCompleteAttempt(r *request.Request) {
70	rt.curAttempt.Start = r.AttemptTime
71	rt.curAttempt.Finish = time.Now()
72	rt.curAttempt.Err = r.Error
73
74	if r.Error != nil {
75		rt.AppendError(r.Error)
76	}
77
78	rt.attempts = append(rt.attempts, rt.curAttempt)
79	rt.curAttempt = RequestAttempt{
80		ID:         rt.curAttempt.ID,
81		AttemptNum: rt.curAttempt.AttemptNum + 1,
82	}
83}
84func (rt *RequestTrace) OnComplete(r *request.Request) {
85	rt.finish = time.Now()
86	// Last attempt includes reading the response body
87	if len(rt.attempts) > 0 {
88		rt.attempts[len(rt.attempts)-1].Finish = rt.finish
89	}
90}
91
92func (rt *RequestTrace) Err() error {
93	if len(rt.errs) != 0 {
94		return rt.errs
95	}
96	return nil
97}
98func (rt *RequestTrace) TotalLatency() time.Duration {
99	return rt.finish.Sub(rt.start)
100}
101func (rt *RequestTrace) Attempts() []RequestAttempt {
102	return rt.attempts
103}
104func (rt *RequestTrace) Retries() int {
105	return len(rt.attempts) - 1
106}
107
108func (rt *RequestTrace) getConn(hostPort string) {}
109func (rt *RequestTrace) gotConn(info httptrace.GotConnInfo) {
110	rt.curAttempt.Reused = info.Reused
111}
112func (rt *RequestTrace) putIdleConn(err error) {}
113func (rt *RequestTrace) gotFirstResponseByte() {
114	rt.curAttempt.FirstResponseByte = time.Now()
115}
116func (rt *RequestTrace) got100Continue() {}
117func (rt *RequestTrace) dnsStart(info httptrace.DNSStartInfo) {
118	rt.curAttempt.DNSStart = time.Now()
119}
120func (rt *RequestTrace) dnsDone(info httptrace.DNSDoneInfo) {
121	rt.curAttempt.DNSDone = time.Now()
122}
123func (rt *RequestTrace) connectStart(network, addr string) {
124	rt.curAttempt.ConnectStart = time.Now()
125}
126func (rt *RequestTrace) connectDone(network, addr string, err error) {
127	rt.curAttempt.ConnectDone = time.Now()
128}
129func (rt *RequestTrace) tlsHandshakeStart() {
130	rt.curAttempt.TLSHandshakeStart = time.Now()
131}
132func (rt *RequestTrace) tlsHandshakeDone(state tls.ConnectionState, err error) {
133	rt.curAttempt.TLSHandshakeDone = time.Now()
134}
135func (rt *RequestTrace) wroteHeaders() {
136	rt.curAttempt.WroteHeaders = time.Now()
137}
138func (rt *RequestTrace) wait100Continue() {
139	rt.curAttempt.Read100Continue = time.Now()
140}
141func (rt *RequestTrace) wroteRequest(info httptrace.WroteRequestInfo) {
142	rt.curAttempt.RequestWritten = time.Now()
143}
144
145type RequestAttempt struct {
146	Start, Finish time.Time
147	SendStart     time.Time
148	Err           error
149
150	Reused     bool
151	ID         string
152	AttemptNum int
153
154	DNSStart, DNSDone                   time.Time
155	ConnectStart, ConnectDone           time.Time
156	TLSHandshakeStart, TLSHandshakeDone time.Time
157	WroteHeaders                        time.Time
158	RequestWritten                      time.Time
159	Read100Continue                     time.Time
160	FirstResponseByte                   time.Time
161}
162
163func (a RequestAttempt) String() string {
164	const sep = ", "
165
166	var w strings.Builder
167	w.WriteString(a.ID + "-" + strconv.Itoa(a.AttemptNum) + sep)
168	w.WriteString("Latency:" + durToMSString(a.Finish.Sub(a.Start)) + sep)
169	w.WriteString("SDKPreSend:" + durToMSString(a.SendStart.Sub(a.Start)) + sep)
170
171	writeStart := a.SendStart
172	fmt.Fprintf(&w, "ConnReused:%t"+sep, a.Reused)
173	if !a.Reused {
174		w.WriteString("DNS:" + durToMSString(a.DNSDone.Sub(a.DNSStart)) + sep)
175		w.WriteString("Connect:" + durToMSString(a.ConnectDone.Sub(a.ConnectStart)) + sep)
176		w.WriteString("TLS:" + durToMSString(a.TLSHandshakeDone.Sub(a.TLSHandshakeStart)) + sep)
177		writeStart = a.TLSHandshakeDone
178	}
179
180	writeHeader := a.WroteHeaders.Sub(writeStart)
181	w.WriteString("WriteHeader:" + durToMSString(writeHeader) + sep)
182	if !a.Read100Continue.IsZero() {
183		// With 100-continue
184		w.WriteString("Read100Cont:" + durToMSString(a.Read100Continue.Sub(a.WroteHeaders)) + sep)
185		w.WriteString("WritePayload:" + durToMSString(a.FirstResponseByte.Sub(a.RequestWritten)) + sep)
186
187		w.WriteString("RespRead:" + durToMSString(a.Finish.Sub(a.RequestWritten)) + sep)
188	} else {
189		// No 100-continue
190		w.WriteString("WritePayload:" + durToMSString(a.RequestWritten.Sub(a.WroteHeaders)) + sep)
191
192		if !a.FirstResponseByte.IsZero() {
193			w.WriteString("RespFirstByte:" + durToMSString(a.FirstResponseByte.Sub(a.RequestWritten)) + sep)
194			w.WriteString("RespRead:" + durToMSString(a.Finish.Sub(a.FirstResponseByte)) + sep)
195		}
196	}
197
198	return w.String()
199}
200
201func durToMSString(v time.Duration) string {
202	ms := float64(v) / float64(time.Millisecond)
203	return fmt.Sprintf("%0.6f", ms)
204}
205