The C code that I can see doesn't seem to be comparable, because it using blocking I/O, but Go always nonblocking I/O.

What I see from strace is that the sendfile consistently sends 102400 bytes. But for some reason the read in the client only reads 65536 bytes. So it makes another read system call to complete the io.ReadFull. The first time, that read completes immediately, returning the remaining 36864 bytes. The subsequent times, that second read returns EAGAIN. So the program adds the descriptor to epoll, and waits for it to become readable. When that happens, the read returns 36864.

If I change the file size to 65536, every loop iteration takes roughly the same amount of time.

I don't know why the kernel is only returning 65536 bytes for the first read, and I don't know why a second following read returns EAGAIN for the subsequent loop iterations.

@ianlancetaylor indeed it seems like the client is the issue look at strace. But it's still weird that changing the server to not use sendfile or the blocking IO C implementation makes it fast. It seems to be some timing issue. When I put a time.Sleep(time.Millisecond*100) in the client for loop everything becomes fast again.

But the timing issue always seems present when using net/http. The following program demonstrate this: https://gist.github.com/erikdubbelboer/3eebecc551245a3b1d5f06a9ef433654#file-benchhttp-go

The output I get from this program is:

$ go run benchhttp.go
2.107016ms
624.168µs
668.172µs
670.807µs
632.343µs
554.222µs
529.344µs
625.901µs
606.854µs
598.888µs

But when I remove client.CloseIdleConnections() to use a keep-alive connection the output is:

$ go run benchhttp.go
2.637642ms
447.034µs
205.563976ms
206.852669ms
207.015865ms
211.073544ms
211.069326ms
207.004693ms
211.057584ms
207.053117ms

As you can see even with the time.Sleep(time.Second) still in place the response is much slower. Removing the time.Sleep doesn't affect the response time at all.

Again wrapping the http.ResponseWriter in a writerOnly{} (to not use sendfile) fixes the issue and makes the responses slightly faster as not using a keep-alive connection.

I'm wondering if this is a deeper issue we can fix or if we should at least make it so net/http doesn't use sendfile on keep-alive connections?

As I test, the C code also behaves similarly to go, If the count param of sendfile larger than the file size (go default is 4194304).

Change https://golang.org/cl/305229 mentions this issue: net: use the size be sent as the count param of sendfile

This indeed seems to fix the problem. You can test this by passing an io.LimitReader(fd, size) instead of just fd to trigger remain to be set to the correct size instead of 4194304.

Running a server and a client on the same system is not the common case, and is not the case for which we should optimize. Can you do some measurements where the two programs are on different systems? Thanks.

I have done some tests between servers with <1ms latency and with ~6ms latency and in both cases it's not noticeable. So I'm guessing its indeed some weird behavior with nonblocking I/O and sendfile where all streams are on the same machine.

Running a server and a client on the same system is not the common case, and is not the case for which we should optimize. Can you do some measurements where the two programs are on different systems? Thanks.

It's semi common when you run a https server that proxies to multiple microservices on the same machine.

I write a non-blocking IO framework, and tried the sendfile test, it seems to work fine on the non-blocking fd:
https://gist.github.com/lesismal/d63098add20868d2b71a2168483ef891

Output:

go run bench.go 
277.042µs
237.266µs
288.234µs
219.801µs
238.872µs
260.966µs
274.589µs
265.921µs
205.281µs
250.087µs

erikdubbelboer's std version:
https://gist.github.com/erikdubbelboer/3eebecc551245a3b1d5f06a9ef433654#file-bench-go

go run ./std.go 
486.578µs
209.483756ms
207.547278ms
208.009642ms
43.189515ms
208.18629ms
208.294767ms
43.925097ms
211.092839ms
208.350165ms

both were run on my laptop, same ubuntu VM.

I write a non-blocking IO framework, and tried the sendfile test, it seems to work fine on the non-blocking fd:
https://gist.github.com/lesismal/d63098add20868d2b71a2168483ef891

https://github.com/lesismal/nbio/blob/517442a262d0e26fecf1a380cddd403ae70bdb14/sendfile_linux.go#L32, your sendfile use the size of the file, this is the thing.

I write a non-blocking IO framework, and tried the sendfile test, it seems to work fine on the non-blocking fd:
https://gist.github.com/lesismal/d63098add20868d2b71a2168483ef891

https://github.com/lesismal/nbio/blob/517442a262d0e26fecf1a380cddd403ae70bdb14/sendfile_linux.go#L32, your sendfile use the size of the file, this is the thing.

You are right, I tried a larger size, then get a slower result, same as the io.Copy and c code.

I tried another test: set the read buffer size for the new connection to be large enough before the data interaction started. The new test performs better than the original one:
https://gist.github.com/lesismal/d63098add20868d2b71a2168483ef891#file-bench_readbuffer-go

Output:

default read buffer:
309.454µs
209.564193ms
207.495256ms
206.871764ms
46.101953ms
205.103742ms
210.380848ms
44.039169ms
210.697342ms
209.346464ms

read buffer 1024*1000:
218.201µs
142.148µs
138.761µs
102.964µs
86.283µs
72.657µs
72.307µs
120.246µs
257.105µs
153.59µs

The kernel implementation of sendfile relies on splice, I read the kernel code but not familiar and not sure about it:
https://github.com/torvalds/linux/blob/master/fs/read_write.c#L1254
I guess the zero-copy process of splice may wait for several RTTs to confirm that there is enough read buffer for the other side to receive the incoming size from the application layer of the server which is larger than the file size.

As I test, the C code also behaves similarly to go, If the count param of sendfile larger than the file size (go default is 4194304).

it seems better to use the size of the file:
https://github.com/golang/go/blob/master/src/net/sendfile_linux.go#L21

as https://github.com/golang/go/blob/master/src/net/sendfile_unix_alt.go#L43 did

Rediscovered as #61530