Timing of requests in goroutines

Question

I am trying to time how long it takes to make concurrent requests. My timing results are about four times slower than what ab2 reports.

I've tried timing requests in two different ways, both of which lead to similar results (which are far off ab2's results). To give an example, ab2 will report the longest request to last 2 milliseconds on a local server, whereas this code will report up to 4.5 milliseconds. By the way, the whole codebase is available here.

How do I properly time a request in go?

Method 1: timing includes more than just the request

From this commit.

// Let's spawn all the requests, with their respective concurrency.
wg.Add(r.Repeat)
r.doneWg.Add(r.Repeat)
for rno := 1; rno <= r.Repeat; rno++ {
    go func(no int, greq goreq.Request) {
        r.ongoingReqs <- struct{}{} // Adding sentinel value to limit concurrency.
        startTime := time.Now()
        greq.Uri = r.URL.Generate()
        gresp, err := greq.Do()
        if err != nil {
            log.Critical("could not send request to #%d %s: %s", no, r.URL, err)
        } else if no < r.Repeat {
            // We're always using the last response for the next batch of requests.
            gresp.Body.Close()
        }
        <-r.ongoingReqs // We're done, let's make room for the next request.
        resp := Response{Response: gresp, duration: time.Now().Sub(startTime)}
        // Let's add that request to the list of completed requests.
        r.doneChan <- &resp
        runtime.Gosched()
    }(rno, greq)
}

Method 2: using an internal function with a defer statement

From this commit.

// Let's spawn all the requests, with their respective concurrency.
wg.Add(r.Repeat)
r.doneWg.Add(r.Repeat)
for rno := 1; rno <= r.Repeat; rno++ {
    go func(no int, greq goreq.Request) {
        r.ongoingReqs <- struct{}{} // Adding sentinel value to limit concurrency.
        greq.Uri = r.URL.Generate()
        var duration time.Duration
        gresp, err := func(dur *time.Duration) (gresp *goreq.Response, err error) {
            defer func(startTime time.Time) { *dur = time.Now().Sub(startTime) }(time.Now())
            return greq.Do()
        }(&duration)

        if err != nil {
            log.Critical("could not send request to #%d %s: %s", no, r.URL, err)
        } else if no < r.Repeat {
            // We're always using the last response for the next batch of requests.
            gresp.Body.Close()
        }
        <-r.ongoingReqs // We're done, let's make room for the next request.
        resp := Response{Response: gresp, duration: duration}
        // Let's add that request to the list of completed requests.
        r.doneChan <- &resp
        runtime.Gosched()
    }(rno, greq)
}

I had a look at this question, which did not help.

Answer 1

As your goroutines enter syscall (writing to a socket), they are preempted. This means that they are interrupted and another goroutine will run in their place. Eventually, your preempted goroutine will be scheduled again and it will continue running where it left off. This doesn't necessarily happen exactly after the syscall is done, though.

Timing in a goroutine is difficult, because even if you did everything serially, Go 1.5's garbage collector will run occasionally, interrupting your theoretical serial loop.

The only real solution is a bit complex:

1. Use RawSyscall directly.
2. Annotate your function with //go:nosplit to prevent it from being preempted.
3. Disable garbage collector.

Even then, I might be forgetting something.