Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

net/http: HTTP Client slows down over time until stop #66643

Closed
Xpl0itU opened this issue Apr 2, 2024 · 12 comments
Closed

net/http: HTTP Client slows down over time until stop #66643

Xpl0itU opened this issue Apr 2, 2024 · 12 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Performance WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Milestone

Comments

@Xpl0itU
Copy link

Xpl0itU commented Apr 2, 2024

Go version

go version go1.22.1 darwin/arm64

Output of go env in your module/workspace:

GO111MODULE=''
GOARCH='arm64'
GOBIN=''
GOCACHE='/Users/samuel/Library/Caches/go-build'
GOENV='/Users/samuel/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/samuel/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/samuel/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/opt/homebrew/Cellar/go/1.22.1/libexec'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/opt/homebrew/Cellar/go/1.22.1/libexec/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.22.1'
GCCGO='gccgo'
AR='ar'
CC='cc'
CXX='c++'
CGO_ENABLED='1'
GOMOD='/dev/null'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/_d/2vjckm5d3yxdmzhhnp98g6d80000gn/T/go-build3829565057=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

Here's the client:

t := http.DefaultTransport.(*http.Transport).Clone()
t.MaxIdleConns = 100
t.MaxConnsPerHost = 100
t.MaxIdleConnsPerHost = 100

client := &http.Client{
    Timeout:   time.Duration(30) * time.Second,
    Transport: t,
}

Here are the functions:

func calculateDownloadSpeed(downloaded int64, startTime, endTime time.Time) int64 {
	duration := endTime.Sub(startTime).Seconds()
	if duration > 0 {
		return int64(float64(downloaded) / duration)
	}
	return 0
}

func downloadFile(ctx context.Context, progressReporter ProgressReporter, client *http.Client, downloadURL, dstPath string, doRetries bool, buffer []byte) error {
	filePath := filepath.Base(dstPath)

	var startTime time.Time

	for attempt := 1; attempt <= maxRetries; attempt++ {
		req, err := http.NewRequestWithContext(ctx, "GET", downloadURL, nil)
		if err != nil {
			return err
		}

		req.Header.Set("User-Agent", "WiiUDownloader")
		req.Header.Set("Connection", "Keep-Alive")
		req.Header.Set("Accept-Encoding", "")

		resp, err := client.Do(req)
		if err != nil {
			return err
		}
		defer resp.Body.Close()

		if resp.StatusCode != http.StatusOK {
			if doRetries && attempt < maxRetries {
				time.Sleep(retryDelay)
				continue
			}
			return fmt.Errorf("download error after %d attempts, status code: %d", attempt, resp.StatusCode)
		}

		file, err := os.Create(dstPath)
		if err != nil {
			return err
		}
		defer file.Close()

		var downloaded int64

		startTime = time.Now()
		ticker := time.NewTicker(250 * time.Millisecond)
		defer ticker.Stop()

		go func() {
			for range ticker.C {
				if progressReporter.Cancelled() {
					break
				}
				progressReporter.UpdateDownloadProgress(downloaded, calculateDownloadSpeed(downloaded, startTime, time.Now()), filePath)
			}
		}()

	Loop:
		for {
			select {
			case <-ctx.Done():
				return ctx.Err()
			default:
				n, err := resp.Body.Read(buffer)
				if err != nil && err != io.EOF {
					if doRetries && attempt < maxRetries {
						time.Sleep(retryDelay)
						break
					}
					return fmt.Errorf("download error after %d attempts: %+v", attempt, err)
				}

				if n == 0 {
					break Loop
				}

				_, err = file.Write(buffer[:n])
				if err != nil {
					if doRetries && attempt < maxRetries {
						time.Sleep(retryDelay)
						break
					}
					return fmt.Errorf("write error after %d attempts: %+v", attempt, err)
				}

				downloaded += int64(n)
			}
		}
		break
	}

	return nil
}

What did you see happen?

For some users, file downloading starts at full speeds but then decreases over time until it stops, this didn't happen on Go 1.21.6.

What did you expect to see?

Speeds should be stable over time.

@artyom
Copy link
Member

artyom commented Apr 2, 2024

@Xpl0itU not commenting on the issue itself, but there's a bug in your code that may attribute to effects you observe: notice that defer calls in downloadFile function only run when function exits, not when a single loop iteration ends. So depending on the number of retries made in a loop, you may defer more and more resp.Body.Close() and file.Close() calls until downloadFile function ends.

@rittneje
Copy link

rittneje commented Apr 2, 2024

To add to what @artyom said, each iteration of the outer loop is also leaking both a ticker and the associated goroutine for calling UpdateDownloadProgress until downloadFile exits. (It should also be noted the goroutine is leaked forever, as stopping the ticker does not cause the goroutine to exit.)

Also, there are two places in the inner loop where it seems like your intent was to do another iteration of the outer loop. (Namely, where resp.Body.Read or file.Write returns an error.) However, your code as written will not do this - it will instead break out of the inner loop, and then immediately break out of the outer loop.

@Xpl0itU
Copy link
Author

Xpl0itU commented Apr 2, 2024

This message also appears when the download stops after 5 attempts
Screenshot_2024-04-02_at_16 09 04

@dmitshur dmitshur added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Apr 2, 2024
@dmitshur dmitshur added this to the Backlog milestone Apr 2, 2024
@dmitshur
Copy link
Contributor

dmitshur commented Apr 2, 2024

CC @neild.

@Xpl0itU
Copy link
Author

Xpl0itU commented Apr 2, 2024

Updated the code and there are still issues:

func downloadFile(ctx context.Context, progressReporter ProgressReporter, client *http.Client, downloadURL, dstPath string, doRetries bool, buffer []byte) error {
	filePath := filepath.Base(dstPath)

	startTime := time.Now()
	ticker := time.NewTicker(250 * time.Millisecond)
	defer ticker.Stop()
	isError := false

	updateProgress := func(downloaded *int64) {
		for range ticker.C {
			if progressReporter.Cancelled() {
				break
			}
			progressReporter.UpdateDownloadProgress(*downloaded, calculateDownloadSpeed(*downloaded, startTime, time.Now()), filePath)
		}
	}

	for attempt := 1; attempt <= maxRetries; attempt++ {
		isError = false
		req, err := http.NewRequestWithContext(ctx, "GET", downloadURL, nil)
		if err != nil {
			return err
		}

		req.Header.Set("User-Agent", "WiiUDownloader")
		req.Header.Set("Connection", "Keep-Alive")
		req.Header.Set("Accept-Encoding", "")

		resp, err := client.Do(req)
		if err != nil {
			return err
		}

		if resp.StatusCode != http.StatusOK {
			if doRetries && attempt < maxRetries {
				time.Sleep(retryDelay)
				continue
			}
			resp.Body.Close()
			return fmt.Errorf("download error after %d attempts, status code: %d", attempt, resp.StatusCode)
		}

		file, err := os.Create(dstPath)
		if err != nil {
			resp.Body.Close()
			return err
		}

		var downloaded int64

		go updateProgress(&downloaded)

	Loop:
		for {
			select {
			case <-ctx.Done():
				resp.Body.Close()
				file.Close()
				return ctx.Err()
			default:
				n, err := resp.Body.Read(buffer)
				if err != nil && err != io.EOF {
					resp.Body.Close()
					file.Close()
					if doRetries && attempt < maxRetries {
						time.Sleep(retryDelay)
						isError = true
						break Loop
					}
					return fmt.Errorf("download error after %d attempts: %+v", attempt, err)
				}

				if n == 0 {
					resp.Body.Close()
					file.Close()
					break Loop
				}

				_, err = file.Write(buffer[:n])
				if err != nil {
					resp.Body.Close()
					file.Close()
					if doRetries && attempt < maxRetries {
						time.Sleep(retryDelay)
						isError = true
						break Loop
					}
					return fmt.Errorf("write error after %d attempts: %+v", attempt, err)
				}

				downloaded += int64(n)
			}
		}
		if !isError {
			break
		}
	}

	return nil
}

@seankhliao
Copy link
Member

are you sure this isn't the server throttling the response?

@Xpl0itU
Copy link
Author

Xpl0itU commented Apr 2, 2024

Yes, other programs that access the same server work just fine

@seankhliao
Copy link
Member

can we get a complete/standalone reproducer for the issue?

@Xpl0itU
Copy link
Author

Xpl0itU commented Apr 2, 2024

I can’t reproduce the issue locally now, but some of my users can reproduce it with the software, but downloading a large file using the attached function should be enough

@Xpl0itU
Copy link
Author

Xpl0itU commented Apr 9, 2024

Still happening with 1.22.2, at least on all major amd64 platforms (linux, windows and darwin)

@seankhliao
Copy link
Member

Without a standalone reproducer, I don't think we can do anything with this issue.

@seankhliao seankhliao added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Apr 9, 2024
@Xpl0itU
Copy link
Author

Xpl0itU commented Apr 14, 2024

Fixed by tweaking my http.Client, here are the working settings:

client := &http.Client{
		Transport: &http.Transport{
			Dial: (&net.Dialer{
				Timeout:   30 * time.Second,
				KeepAlive: 30 * time.Second,
			}).Dial,
			MaxIdleConns:          100,
			MaxIdleConnsPerHost:   100,
			MaxConnsPerHost:       100,
			IdleConnTimeout:       90 * time.Second,
			TLSHandshakeTimeout:   10 * time.Second,
			ResponseHeaderTimeout: 10 * time.Second,
			ExpectContinueTimeout: 1 * time.Second,
		},
	}

@Xpl0itU Xpl0itU closed this as completed Apr 14, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Performance WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Development

No branches or pull requests

5 participants