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

[tmm1]

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]

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]

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]

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

[tmm1]

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]

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]

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]

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]

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]

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