Go by Example: http/httptrace

ref: Go (Golang) httptrace Tutorial

ref: Golang - Request test using net/http/httptrace

doc: Go doc: httptrace

1) HTTP Request/Response - Trace Events

 - DNS Request - DNSStart

 - DNS Response - DNSDone

 - TCP Create Connection - ConnectStart/ConnectDone

 - Write to the TCP connection - WroteHeaders/WroteRequest

 - Read from TCP Connection - GotFirstResponseByte

 - Close TCP Connection

2) HTTP Persitent Connections

    - If TCP Connection already exists use it

 - Write to the TCP connection - WroteHeaders/WroteRequest

 - Read from TCP Connection - GotFirstResponseByte

 - Keep Connection alive for later use - PutIdleConn

package main

import (
    "fmt"
    "io"
    "io/ioutil"
    "log"
    "net/http"
    "net/http/httptrace"
    "time"
)

tracer for time tracking

 
type Tracer struct {
    start time.Time
    end   time.Time
}

func (t *Tracer) GetConn(hostPort string) {
    fmt.Printf("GetConn(%s) %d ms\n", hostPort, time.Since(t.start).Milliseconds())
}
func (t *Tracer) DNSStart(info httptrace.DNSStartInfo) {
    fmt.Printf("DNSStart(%+v) %d ms\n", info, time.Since(t.start).Milliseconds())
}
func (t *Tracer) DNSDone(info httptrace.DNSDoneInfo) {
    fmt.Printf("DNSDone(%+v) %d ms\n", info, time.Since(t.start).Milliseconds())
}
func (t *Tracer) ConnectStart(network, addr string) {
    fmt.Printf("ConnectStart(%s, %s) %d ms\n", network, addr, time.Since(t.start).Milliseconds())
}
func (t *Tracer) ConnectDone(network, addr string, err error) {
    fmt.Printf("ConnectDone(%s, %s, %v) %d ms\n", network, addr, err,
        time.Since(t.start).Milliseconds())
}
func (t *Tracer) GotConn(info httptrace.GotConnInfo) {
    fmt.Printf("GotConn(%+v) %d ms\n", info, time.Since(t.start).Milliseconds())
}
func (t *Tracer) GotFirstResponseByte() {
    t.end = time.Now()
    fmt.Printf("GotFirstResponseByte (delay) %d ms\n", time.Since(t.start).Milliseconds())
}

func (t *Tracer) PutIdleConn(err error) {
    t.end = time.Now()
    fmt.Printf("PutIdleConn(%+v) %d ms\n", err, time.Since(t.start).Milliseconds())
}

Create Trace Info

 
func createTrace() *httptrace.ClientTrace {
    tracer := Tracer{start: time.Now()}
    trace := &httptrace.ClientTrace{
        GetConn:              tracer.GetConn,
        DNSStart:             tracer.DNSStart,
        DNSDone:              tracer.DNSDone,
        ConnectStart:         tracer.ConnectStart,
        ConnectDone:          tracer.ConnectDone,
        GotConn:              tracer.GotConn,
        GotFirstResponseByte: tracer.GotFirstResponseByte,

called when connection is put back to connection pool

 
        PutIdleConn: tracer.PutIdleConn,
    }
    return trace
}

const url = "http://example.com"

func main() {
    req, err := http.NewRequest(http.MethodGet, url, nil)
    if err != nil {
        log.Fatal(err)
    }
    trace := createTrace()

Create Trace context

 
    ctx := httptrace.WithClientTrace(req.Context(), trace)

Attach Trace context to request

 
    req = req.WithContext(ctx)

    fmt.Println("1st Request to", url)
    fmt.Println("")

    res, err := http.DefaultClient.Do(req)
    if err != nil {
        log.Fatal(err)
    }

read the whole body and close so that the underlying TCP conn is re-used

 
    io.Copy(ioutil.Discard, res.Body)
    res.Body.Close()

Create Trace context

 
    fmt.Println("")
    fmt.Println("2nd Request to", url)
    fmt.Println("")
    req2, err := http.NewRequest(http.MethodGet, url, nil)
    if err != nil {
        log.Fatal(err)
    }
    trace = createTrace()

    ctx = httptrace.WithClientTrace(req2.Context(), trace)

Attach Trace context to request

 
    req = req.WithContext(ctx)
    _, err = http.DefaultClient.Do(req)
    if err != nil {
        log.Fatal(err)
    }
}

$ go run http-trace.go
1st Request to http://example.com
 
GetConn(example.com:80) 0 ms
DNSStart({Host:example.com}) 0 ms
DNSDone({Addrs:[{IP:2606:2800:220:1:248:1893:25c8:1946 Zone:} {IP:93.184.216.34 Zone:}] 
Err:<nil> Coalesced:false}) 11 ms
ConnectStart(tcp, [2606:2800:220:1:248:1893:25c8:1946]:80) 11 ms
ConnectDone(tcp, [2606:2800:220:1:248:1893:25c8:1946]:80, <nil>) 152 ms
GotConn({Conn:0x14000094000 Reused:false WasIdle:false IdleTime:0s}) 152 ms
GotFirstResponseByte (delay) 293 ms
PutIdleConn(<nil>) 294 ms
 
2nd Request to http://example.com
 
GetConn(example.com:80) 0 ms
GotConn({Conn:0x14000094000 Reused:true WasIdle:true IdleTime:152.916µs}) 0 ms
GotFirstResponseByte (delay) 140 ms

for 1st Request, we can see PutIdleConn is called. for 2nd Request, DNS resolving part is skipped cuz it reused the previous connection.

Next example: sync.RWMutex.

source
Forked from Go by Example