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: slow http.ServeFile performance on Windows VM #30082

Closed
tmm1 opened this issue Feb 4, 2019 · 11 comments
Closed

net/http: slow http.ServeFile performance on Windows VM #30082

tmm1 opened this issue Feb 4, 2019 · 11 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Windows Performance
Milestone

Comments

@tmm1
Copy link
Contributor

tmm1 commented Feb 4, 2019

What version of Go are you using (go version)?

$ go version
go version go1.11.4 windows/amd64

Does this issue reproduce with the latest release?

I tried 1.9.7 and 1.10.7 with the same results. I assume 1.11.5 is the same as there are no new relevant commits.

What operating system and processor architecture are you using (go env)?

go env Output
$ go env
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\micro\AppData\Local\go-build
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOOS=windows
set GOPATH=C:\Users\micro\go
set GOPROXY=
set GORACE=
set GOROOT=C:\Go
set GOTMPDIR=
set GOTOOLDIR=C:\Go\pkg\tool\windows_amd64
set GCCGO=gccgo
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=C:\Users\micro\AppData\Local\Temp\go-build335086354=/tmp/go-build -gno-record-gcc-switches

What did you do?

I have a 4.2ghz i7 iMac, which is running macOS 10.14.2

On the iMac, I'm also using VirtualBox to run a VM with Windows 10 Pro 10.0.17134 Build 17134

I have a 1.65GB video file named stream.mpg that exists both on my macOS host and inside the VM.

I'm using the following go program to serve up that file via http:

package main

import (
	"net/http"
)

func main() {
	http.HandleFunc("/stream.mpg", func(w http.ResponseWriter, r *http.Request) {
		http.ServeFile(w, r, "stream.mpg")
	})
	http.ListenAndServe(":9000", nil)
}

I'm running this server both on macOS and Windows. The macOS host is 10.0.1.10 and the Windows VM is 10.0.1.20

I observe the following results when using curl to download the file to measure download speed/time. Note the "Average DLoad" and "Time Total" columns in the middle. Each result below is the best of three runs. (The first result not shown is usually much slower, as the file is not memory mapped into the fs cache yet).

Windows <- Windows

tmm1@windows $ curl.exe -o nul http://10.0.1.20:9000/stream.mpg
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 1651M  100 1651M    0     0   550M      0  0:00:03  0:00:03 --:--:--  ---

Windows <- macOS

tmm1@windows $ curl.exe -o nul http://10.0.1.10:9000/stream.mpg
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 1651M  100 1651M    0     0   550M      0  0:00:03  0:00:03 --:--:--  ---

macOS <- macOS

tmm1@macos $ curl -o /dev/null http://10.0.1.10:9000/stream.mpg
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 1651M  100 1651M    0     0  1643M      0  0:00:01  0:00:01 --:--:-- ---

macOS <- Windows

tmm1@macos $ curl -o /dev/null http://10.0.1.20:9000/stream.mpg
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 1651M  100 1651M    0     0   143M      0  0:00:11  0:00:11 --:--:--  ---

What did you expect to see?

Similar speeds when serving the file from Windows and macOS.

What did you see instead?

When running the server on macOS, the local host can download 1.65GB in 1s, and the Windows VM can download the file in 3s.

When running the server on Windows, the local VM can download 1.65GB in 3s, but the host takes over 11s to fetch the file and maxes out at 145Mbps.

I've observed the same behavior with physical hosts, and the VMs in this test were only setup to remove any network hardware from the test.

@tmm1
Copy link
Contributor Author

tmm1 commented Feb 4, 2019

I decided to compare some other servers to see what kind of speeds they get in the same setup. In the Windows VM, I ran nodejs serve on port 5000, and python3 http.serve on port 4000.

Python serves up the file slightly slower than golang, but nodejs is much faster than both.

macOS <- Windows (golang port 9000)

tmm1@macos $ curl -o /dev/null http://10.0.1.20:9000/stream.mpg
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 1651M  100 1651M    0     0   141M      0  0:00:11  0:00:11 --:--:--  ---

macOS <- Windows (nodejs port 5000)

tmm1@macos $ curl -o /dev/null http://10.0.1.20:5000/stream.mpg
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 1651M  100 1651M    0     0   192M      0  0:00:08  0:00:08 --:--:--  ---

macOS <- Windows (python port 4000)

tmm1@macos $ curl -o /dev/null http://10.0.1.20:4000/stream.mpg
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 1651M  100 1651M    0     0   132M      0  0:00:12  0:00:12 --:--:--  ---

@tmm1
Copy link
Contributor Author

tmm1 commented Feb 5, 2019

I also tried nginx (on port 80), which is the fastest so far but still similar to the 8s nodejs result:

tmm1@macos $ curl -o /dev/null http://10.0.1.20/stream.mpg
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 1651M  100 1651M    0     0   206M      0  0:00:08  0:00:08 --:--:--  ---

I think this proves there is some sort of bottleneck in the golang runtime which is limiting throughput at around ~150MB/s, and causing the same file to take 37% longer to upload (8s vs 11s).

cc @ianlancetaylor @alexbrainman

@alexbrainman
Copy link
Member

I'm using the following go program to serve up that file via http:

I am not an expert in performance tuning. But, I think, your setup / source code has too many moving parts - you use http server, you use VM. The slow down can be anywhere.

I expect your code uses syscall.TransmitFile optimisation

https://github.com/golang/go/blob/master/src/internal/poll/sendfile_windows.go

It might help, or might hurt. See, if you do use syscall.TransmitFile or not. Adjust your code, so you could try both "with syscall.TransmitFile" and "without syscall.TransmitFile" versions.

If that does not help, maybe try and replace net/http package with simple custom TCP implementation. See if that makes any difference.

I don't see how I could reproduce your problem here. And, even if I do, I would need C source of your alternative program to be able to try and reproduce your top performance with Go.

Alex

@andybons andybons changed the title Slow http.ServeFile performance on Windows net/http: slow http.ServeFile performance on Windows Feb 5, 2019
@andybons andybons changed the title net/http: slow http.ServeFile performance on Windows net/http: slow http.ServeFile performance on Windows VM Feb 5, 2019
@andybons andybons added OS-Windows NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Feb 5, 2019
@andybons andybons added this to the Unplanned milestone Feb 5, 2019
@tmm1
Copy link
Contributor Author

tmm1 commented Feb 8, 2019

If that does not help, maybe try and replace net/http package with simple custom TCP implementation. See if that makes any difference.

No difference with the following:

package main

import (
	"fmt"
	"io"
	"net"
	"os"
)

func main() {
	server, err := net.Listen("tcp", ":27001")
	if err != nil {
		fmt.Println("Error listetning: ", err)
		os.Exit(1)
	}
	defer server.Close()
	fmt.Println("Server started! Waiting for connections...")
	for {
		connection, err := server.Accept()
		if err != nil {
			fmt.Println("Error: ", err)
			os.Exit(1)
		}
		go sendFileToClient(connection)
	}
}

func sendFileToClient(connection net.Conn) {
	fmt.Println("A client has connected!")
	defer connection.Close()
	file, err := os.Open("stream.mpg")
	if err != nil {
		fmt.Println(err)
		return
	}
	defer file.Close()
	io.Copy(connection, file)
	fmt.Println("File has been sent, closing connection!")
}

I believe io.Copy will use TransmitFile if possible. In order to rule that out, I replaced io.Copy with the following snippet:

	sendBuffer := make([]byte, 1024*64)
	for {
		_, err = file.Read(sendBuffer)
		if err == io.EOF {
			break
		}
		connection.Write(sendBuffer)
	}

In both cases, using nc to time the downloads from another host results in download times of 12s which translates to ~140MB/s (the same as with http.ServeFile).

I don't see how I could reproduce your problem here. And, even if I do, I would need C source of your alternative program to be able to try and reproduce your top performance with Go.

This should be trivial to reproduce. Run the tcp or http script above on a Windows host to serve up any large file on disk, then download it from another host and measure the speed/time. You will notice that it is impossible to get download speeds above 150MB/s regardless of available network/disk bandwidth.

@alexbrainman
Copy link
Member

Run the tcp or http script above on a Windows host to serve up any large file on disk, then download it from another host and measure the speed/time

I am away from my computer for few weeks. It will have to wait until then.

Alex

@tmm1
Copy link
Contributor Author

tmm1 commented Feb 8, 2019

I am away from my computer for few weeks. It will have to wait until then.

No problem, enjoy your time off!

I will continue to run some tests to see if I can narrow things down further.

@bradfitz
Copy link
Contributor

I have a 1.65GB video file named stream.mpg that exists both on my macOS host and inside the VM.

Do you mean that from inside your VirtualBox Windows VM you're serving a file that's using one of those funky shared filesystems that shares files from your host?

If so, this bug is not actionable or very important. Those funky filesystems are for ease of development but not for production. It's very likely they're just not very performant.

@tmm1
Copy link
Contributor Author

tmm1 commented Feb 11, 2019

Do you mean that from inside your VirtualBox Windows VM you're serving a file that's using one of those funky shared filesystems that shares files from your host?

No, I have a separate copy I downloaded into the VM, and am not using any shared filesystem.

nginx and nodejs can serve up the file at 200MB/s, but golang never goes over 150MB/s

I'll find some time this week to boot up a physical Windows host and re-run the tests, just to rule out the VM altogether.

@alexbrainman
Copy link
Member

This should be trivial to reproduce.

I downloaded curl for windows (from https://curl.haxx.se/windows/ ), and tried running your program and curl.exe on my Windows PC.

C:\Users\Alex\AppData\Local\Temp\a\curl-7.64.0-win64-mingw\bin>curl --version
curl 7.64.0 (x86_64-pc-win32) libcurl/7.64.0 OpenSSL/1.1.1a (Schannel) zlib/1.2.11 brotli/1.0.7 W
inIDN libssh2/1.8.0 nghttp2/1.36.0
Release-Date: 2019-02-06
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtsp scp sftp sm
b smbs smtp smtps telnet tftp
Features: AsynchDNS IDN IPv6 Largefile SSPI Kerberos SPNEGO NTLM SSL libz brotli TLS-SRP HTTP2 HTTPS-proxy MultiSSL

C:\Users\Alex\AppData\Local\Temp\a\curl-7.64.0-win64-mingw\bin>curl -o nul http://localhost:9000/stream.mpg
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0 1640M    0 32768    0     0  1391k      0  0:20:07 --:--:--  0:20:07 1391k
curl: (23) Failed writing body (0 != 16384)

C:\Users\Alex\AppData\Local\Temp\a\curl-7.64.0-win64-mingw\bin>curl -o a.txt http://localhost:9000/stream.mpg
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 1640M  100 1640M    0     0  36.4M      0  0:00:44  0:00:44 --:--:-- 21.8M

C:\Users\Alex\AppData\Local\Temp\a\curl-7.64.0-win64-mingw\bin>

It looks like curl -o nul is broken. And if write output to a file, I get average speed of 36.4M.

What do I do now?

Alex

@tmm1
Copy link
Contributor Author

tmm1 commented Apr 9, 2019

It looks like curl -o nul is broken.

This was apparently a bug in 7.64.0 and is fixed in the new 7.64.1 release available at https://curl.haxx.se/windows/

(Note also that modern versions of Windows 10 ship with curl @ c:\windows\system32\curl.exe).

@tmm1
Copy link
Contributor Author

tmm1 commented Apr 10, 2019

I started fresh on a physical windows machine with go1.12.2, and I figured out one source of my confusion:

curl's speed numbers are reported in MB/s (i.e. bytes not bits). On a gigabit network, the maximum possible throughput would be 1000/8 = ~125MB/s. So the higher numbers I was seeing before were only possible because the data was traveling over a loopback or virtual VM interface not limited by gigabit hardware.

Next, I added an endpoint that just serves up zeros to rule out anything disk/file related:

	http.HandleFunc("/empty", func(w http.ResponseWriter, r *http.Request) {
		data := make([]byte, 4096)
		for {
			_, err := w.Write(data)
			if err != nil {
				break
			}
		}
	})

I hit this endpoint from another machine and confirmed I was able to achieve ~110MB/s against both a macOS server and Windows server.

Then, I tried again with the stream.mpg endpoint and confirmed again that I'm getting ~110MB/s regardless of what OS the golang server is running on.

It's clear this bug as originally described is not present, or if it was it is no longer in go1.12.

@tmm1 tmm1 closed this as completed Apr 10, 2019
@golang golang locked and limited conversation to collaborators Apr 9, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Windows Performance
Projects
None yet
Development

No branches or pull requests

5 participants