Why are IO operations slower in Goroutines?

Question

I am working on IO after downloading an image from a goroutine.

A question arose during testing.

After downloading an image in a Goroutine, I found a case where the IO operation was very slow.

Rather, it downloads the image in the Goroutine IO operations outside the groutine realm were faster.

May I know why?

Below is the test source code.

type ImageResult struct {
    TargetImagePath string
    Success         bool
}

type ImageDownloadResult struct {
    TargetImagePath string
    Response        *http.Response
    Success         bool
}

func main() {
    downloadUrls := []string{
        "https://myhost.com/item/image/path/name_01.png",
        "https://myhost.com/item/image/path/name_02.png",
        "https://myhost.com/item/image/path/name_03.png",
        "https://myhost.com/item/image/path/name_05.png",
        "https://myhost.com/item/image/path/name_07.png",
        "https://myhost.com/item/image/path/name_08.png",
        "https://myhost.com/item/image/path/name_09.png",
        "https://myhost.com/item/image/path/name_10.png",
        "https://myhost.com/item/image/path/name_11.png",
        "https://myhost.com/item/image/path/name_12.png",
        "https://myhost.com/item/image/path/name_13.png",
        "https://myhost.com/item/image/path/name_14.png",
        "https://myhost.com/item/image/path/name_16.png",
    }

    startAsyncIO := time.Now()
    resultChannel := make(chan ImageResult)
    for _, downloadUrl := range downloadUrls {
        go HttpFileDownLoadAndIOWithAsync(downloadUrl, resultChannel)
    }

    for i := 0; i < len(downloadUrls); i++ {
        <-resultChannel
    }
    fmt.Println("Total Time Async IO: ", time.Now().Sub(startAsyncIO))

    fmt.Println("=======================VS========================")

    startSyncIO := time.Now()
    resultChannel2 := make(chan ImageDownloadResult)
    for _, downloadUrl := range downloadUrls {
        go HttpFileDownLoadWithAsync(downloadUrl, resultChannel2)

    }

    for i := 0; i < len(downloadUrls); i++ {
        result := <-resultChannel2
        getBytesFromDownloadData(result.Response, result.TargetImagePath)
    }
    fmt.Println("Total Time Sync IO: ", time.Now().Sub(startSyncIO))
}

func HttpFileDownLoadAndIOWithAsync(downloadUrl string, imageResult chan ImageResult) {
    result := ImageResult{
        TargetImagePath: downloadUrl,
    }

    client := http.Client{
        CheckRedirect: func(r *http.Request, via []*http.Request) error {
            r.URL.Opaque = r.URL.Path
            return nil
        },
    }
    // Put content on file
    downStart := time.Now()
    resp, _ := client.Get(downloadUrl)
    downEnd := time.Now()
    fmt.Println(downloadUrl, "File Download Time : ", downEnd.Sub(downStart))

    defer resp.Body.Close()

    // File Read
    ioStart := time.Now()
    var buf bytes.Buffer
    io.Copy(&buf, resp.Body)
    ioEnd := time.Now()
    fmt.Println(downloadUrl, "IO Time Async : ", ioEnd.Sub(ioStart))

    result.Success = true
    imageResult <- result

}

func HttpFileDownLoadWithAsync(downloadUrl string, imageResult chan ImageDownloadResult) {
    result := ImageDownloadResult{
        TargetImagePath: downloadUrl,
    }

    client := http.Client{
        CheckRedirect: func(r *http.Request, via []*http.Request) error {
            r.URL.Opaque = r.URL.Path
            return nil
        },
    }
    // Put content on file
    downStart := time.Now()
    resp, _ := client.Get(downloadUrl)
    downEnd := time.Now()
    fmt.Println(downloadUrl, "File Download Time : ", downEnd.Sub(downStart))

    result.Success = true
    result.Response = resp
    imageResult <- result

}

func getBytesFromDownloadData(resp *http.Response, downloadUrl string) []byte {
    defer func() {
        if err2 := resp.Body.Close(); err2 != nil {
            fmt.Println("Fail Download by image Download Close Error:", downloadUrl)
        }
    }()
    // File Read
    startTime := time.Now()
    var buf bytes.Buffer
    _, err := io.Copy(&buf, resp.Body)

    if err != nil {
        fmt.Println("Fail Download by Read Response Body:", downloadUrl)
        return nil
    }
    fmt.Println(downloadUrl, "IO Time Sync:", time.Now().Sub(startTime))
    return buf.Bytes()
}

Below is the log.

https://myhost.com/item/image/path/name_13.png File Download Time :  197.058394ms
https://myhost.com/item/image/path/name_12.png File Download Time :  399.633804ms
https://myhost.com/item/image/path/name_08.png File Download Time :  587.309339ms
https://myhost.com/item/image/path/name_08.png IO Time Async :  314.482233ms
https://myhost.com/item/image/path/name_03.png File Download Time :  901.985524ms
https://myhost.com/item/image/path/name_05.png File Download Time :  1.132634351s
https://myhost.com/item/image/path/name_02.png File Download Time :  1.132661015s
https://myhost.com/item/image/path/name_14.png File Download Time :  1.132605289s
https://myhost.com/item/image/path/name_09.png File Download Time :  1.132608987s
https://myhost.com/item/image/path/name_16.png File Download Time :  1.133075291s
https://myhost.com/item/image/path/name_01.png File Download Time :  1.132837045s
https://myhost.com/item/image/path/name_11.png File Download Time :  1.133100234s
https://myhost.com/item/image/path/name_10.png File Download Time :  1.132982295s
https://myhost.com/item/image/path/name_07.png File Download Time :  1.133150493s
https://myhost.com/item/image/path/name_12.png IO Time Async :  1.240533838s
https://myhost.com/item/image/path/name_09.png IO Time Async :  849.335303ms
https://myhost.com/item/image/path/name_03.png IO Time Async :  1.080254194s
https://myhost.com/item/image/path/name_02.png IO Time Async :  849.395964ms
https://myhost.com/item/image/path/name_13.png IO Time Async :  1.784857595s
https://myhost.com/item/image/path/name_14.png IO Time Async :  849.642554ms
https://myhost.com/item/image/path/name_16.png IO Time Async :  849.494898ms
https://myhost.com/item/image/path/name_01.png IO Time Async :  850.297187ms
https://myhost.com/item/image/path/name_10.png IO Time Async :  864.482359ms
https://myhost.com/item/image/path/name_11.png IO Time Async :  864.524354ms
https://myhost.com/item/image/path/name_07.png IO Time Async :  874.676604ms
https://myhost.com/item/image/path/name_05.png IO Time Async :  875.22765ms
Total Time Async IO:  2.008162313s
=======================VS========================
https://myhost.com/item/image/path/name_09.png File Download Time :  72.476375ms
https://myhost.com/item/image/path/name_05.png File Download Time :  73.351299ms
https://myhost.com/item/image/path/name_07.png File Download Time :  92.839309ms
https://myhost.com/item/image/path/name_10.png File Download Time :  105.41514ms
https://myhost.com/item/image/path/name_08.png File Download Time :  136.861107ms
https://myhost.com/item/image/path/name_01.png File Download Time :  137.531384ms
https://myhost.com/item/image/path/name_16.png File Download Time :  204.833342ms
https://myhost.com/item/image/path/name_11.png File Download Time :  225.73164ms
https://myhost.com/item/image/path/name_03.png File Download Time :  238.569755ms
https://myhost.com/item/image/path/name_09.png IO Time Sync: 251.986344ms
https://myhost.com/item/image/path/name_14.png File Download Time :  473.071003ms
https://myhost.com/item/image/path/name_02.png File Download Time :  523.402477ms
https://myhost.com/item/image/path/name_13.png File Download Time :  523.389256ms
https://myhost.com/item/image/path/name_12.png File Download Time :  523.412647ms
https://myhost.com/item/image/path/name_05.png IO Time Sync: 549.364233ms
https://myhost.com/item/image/path/name_07.png IO Time Sync: 890.004µs
https://myhost.com/item/image/path/name_10.png IO Time Sync: 545.761µs
https://myhost.com/item/image/path/name_08.png IO Time Sync: 229.321µs
https://myhost.com/item/image/path/name_01.png IO Time Sync: 601.996µs
https://myhost.com/item/image/path/name_16.png IO Time Sync: 12.912227ms
https://myhost.com/item/image/path/name_11.png IO Time Sync: 148.432703ms
https://myhost.com/item/image/path/name_03.png IO Time Sync: 336.862µs
https://myhost.com/item/image/path/name_14.png IO Time Sync: 239.328µs
https://myhost.com/item/image/path/name_02.png IO Time Sync: 483.976µs
https://myhost.com/item/image/path/name_13.png IO Time Sync: 215.655µs
https://myhost.com/item/image/path/name_12.png IO Time Sync: 265.376µs
Total Time Sync IO:  1.039298797s

Not a valid approach to benchmark. Many factors can affect your results here (as the answer provided some). — AminMal, Jul 29 '22 at 11:01

icza · Answer 1 · 2022-07-29T21:24:46.030

Go code is always executed in goroutines.

Goroutines are equal, they are not distinguished (except when the main goroutine running the main() function ends, the whole app is terminated).

Goroutines are scheduled / multiplexed onto OS threads, and threads run on physical or virtual CPU cores. So whether one goroutine runs slower / faster than another depends on how the CPU core executing its instructions is loaded (system-wise). A CPU core eventually executing one goroutine's instructions may be utilized more than another, resulting in worse perceptived goroutine performance, but this is not because of Go's runtime and goroutine scheduling.

Note that it's possible to lock a goroutine to an OS thread using runtime.LockOSThread() which means the goroutine will "own" that thread (no other goroutine will be scheduled onto that thread), but you don't use it in your app.

So you experiencing slower download from other goroutines is not Go related, it may relate to your OS and CPU load or the external service (HTTP server) you call.

Also note that running the same code again may take significantly less time, initialized code may be reused, and connecting to the same host may also be significantly faster: DNS lookups are cached, even TCP connections may be cached / pooled. The server you call may also cache certain data, so fetching the same URLs may also be significantly faster (fetching different resources from the same server may also be faster in subsequent calls, certain checks like authentication / authorization may be cached).

See related: Order of the code and performance

I wrote it in a way that caused misunderstandings due to the lack of content due to my poor English. What I'm curious to know is why the Io.copy operation inside the goroutine is slower. I'm sorry, but I changed the post to something else, can you help me with this?https://stackoverflow.com/questions/73183626/why-is-the-operation-of-the-io-copy-function-inside-a-goroutine-so-slow — user3689808, Jul 31 '22 at 13:26

Why are IO operations slower in Goroutines?

1 Answers1