http_trace.go 3.4 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106
  1. package tos
  2. import (
  3. "crypto/tls"
  4. "fmt"
  5. "net/http"
  6. "net/http/httptrace"
  7. "sync/atomic"
  8. )
  9. type accessLogRequest struct {
  10. clientDnsCost int64
  11. clientDialCost int64
  12. clientTlsHandShakeCost int64
  13. clientSendHeadersAndBodyCost int64
  14. clientWaitResponseCost int64
  15. clientSendRequestCost int64
  16. actionStartMs int64
  17. }
  18. func newAccessLogRequest(actionStartMs int64) *accessLogRequest {
  19. return &accessLogRequest{
  20. clientDnsCost: -1,
  21. clientDialCost: -1,
  22. clientTlsHandShakeCost: -1,
  23. clientSendHeadersAndBodyCost: -1,
  24. clientWaitResponseCost: -1,
  25. clientSendRequestCost: -1,
  26. actionStartMs: actionStartMs,
  27. }
  28. }
  29. func (r *accessLogRequest) PrintAccessLog(logger Logger, req *http.Request, response *http.Response) {
  30. if logger == nil {
  31. return
  32. }
  33. atomic.CompareAndSwapInt64(&r.clientSendRequestCost, -1, GetUnixTimeMs()-r.actionStartMs)
  34. var requestId *string
  35. if response != nil {
  36. requestId = StringPtr(response.Header.Get(HeaderRequestID))
  37. }
  38. prefix := buildPrefix(requestId)
  39. if req != nil {
  40. logger.Debug(fmt.Sprintf("%s, method: %s, host: %s, request uri: %s, dns cost: %d ms, dial cost: %d ms, tls handshake cost: %d ms, send headers and body cost: %d ms, wait response cost: %d ms, request cost: %d ms",
  41. prefix, req.Method, req.URL.Host, req.URL.EscapedPath(), r.clientDnsCost, r.clientDialCost, r.clientTlsHandShakeCost,
  42. r.clientSendHeadersAndBodyCost, r.clientWaitResponseCost, r.clientSendRequestCost))
  43. } else {
  44. logger.Debug(fmt.Sprintf("%s, dns cost: %d ms, dial cost: %d ms, tls handshake cost: %d ms, send headers and body cost: %d ms, wait response cost: %d ms, request cost: %d ms",
  45. prefix, r.clientDnsCost, r.clientDialCost, r.clientTlsHandShakeCost, r.clientSendHeadersAndBodyCost, r.clientWaitResponseCost, r.clientSendRequestCost))
  46. }
  47. }
  48. func buildPrefix(requestId *string) string {
  49. prefix := ""
  50. if requestId != nil {
  51. prefix = fmt.Sprintf("[requestId: %s] %s", *requestId, prefix)
  52. }
  53. return prefix
  54. }
  55. func getClientTrace(actionStartMs int64) (*httptrace.ClientTrace, *accessLogRequest) {
  56. var dnsStart int64
  57. var dialStart int64
  58. var tlsHandShakeStart int64
  59. var sendHeadersAndBodyStart int64
  60. var waitResponseStart int64
  61. r := newAccessLogRequest(actionStartMs)
  62. trace := &httptrace.ClientTrace{
  63. GotFirstResponseByte: func() {
  64. r.clientWaitResponseCost = GetUnixTimeMs() - waitResponseStart
  65. },
  66. DNSStart: func(info httptrace.DNSStartInfo) {
  67. dnsStart = GetUnixTimeMs()
  68. },
  69. DNSDone: func(info httptrace.DNSDoneInfo) {
  70. r.clientDnsCost = GetUnixTimeMs() - dnsStart
  71. },
  72. ConnectStart: func(network, addr string) {
  73. dialStart = GetUnixTimeMs()
  74. },
  75. ConnectDone: func(network, addr string, err error) {
  76. now := GetUnixTimeMs()
  77. sendHeadersAndBodyStart = now
  78. r.clientDialCost = now - dialStart
  79. },
  80. TLSHandshakeStart: func() {
  81. tlsHandShakeStart = GetUnixTimeMs()
  82. },
  83. TLSHandshakeDone: func(state tls.ConnectionState, err error) {
  84. now := GetUnixTimeMs()
  85. sendHeadersAndBodyStart = now
  86. r.clientTlsHandShakeCost = now - tlsHandShakeStart
  87. },
  88. GotConn: func(httptrace.GotConnInfo) {
  89. sendHeadersAndBodyStart = GetUnixTimeMs()
  90. },
  91. WroteRequest: func(info httptrace.WroteRequestInfo) {
  92. waitResponseStart = GetUnixTimeMs()
  93. r.clientSendHeadersAndBodyCost = waitResponseStart - sendHeadersAndBodyStart
  94. },
  95. }
  96. return trace, r
  97. }