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