High memory usage due to Go HTTP2 early close bug

[jonathonl]

I'm trying to reduce memory usage when concurrently reading from many files. I get the following error when trying to limit the readahead buffer with v0.21.0. Is max_readahead not supported?

gcsfuse -o max_readahead=4096 -o nonempty bucket-name /mnt/bucket
Using mount point: /mnt/bucket
Opening GCS connection...
Opening bucket...
Mounting file system...
daemonize.Run: readFromProcess: sub-process: mountWithArgs: mountWithConn: Mount: mount: running fusermount: exit status 1

stderr:
fusermount: mount failed: Invalid argument

[jacobsa]

Can you link to documentation on that argument? It's not clear to me what fusermount is and isn't supposed to support.

[jonathonl]

I'm just basing this off of the general mount options on the man page. I have no idea whether this is a fuse or fuse implementation detail.

My main issue is memory consumption by the gcsfuse process as number of files being read increases (~1.8GiB / 100 files). I suspected that readahead buffers were contributing to this, but that may not be the case. Is there some other configuration that would sacrifice performance for lower memory usage? I can't think of anything other than readahead buffers that would use that much memory.

[jacobsa]

Thanks. I think we'd have to plumb this option to the kernel explicitly, but before then let's figure out what's causing the memory usage. (Ping #226 which may be related.) We can do that with a memory profile.

When you see the high memory usage, could you please send SIGUSR2 to the gcsfuse process (probably via killall -USR2 gcsfuse) to collect a memory profile, and then post /tmp/mem.pprof here? Please also advise which OS and gcsfuse version you're using.

[jacobsa]

It would also be good to run gcsfuse with --foreground and the environment variable GODEBUG=gctrace=1. That will cause Go to print garbage collection stats to stderr.

[jonathonl]

I took 3 memory profiles. The first was taken while my test program was running. The second was taken after GC released 201 MB. The third after a message that said GC succeed (though there was still over 2 GB being used by gcsfuse). Notice that ctrl+c failed until after garbage collection ran.

4.4.0-78-generic (Ubuntu 16.04)
gcsfuse version 0.21.0 (Go version go1.8)

Attached are the the 3 profiles, source code (ran with 500 1GB files) and log output.
gcsfuse_test.zip

[jacobsa]

The memory profile shows that pretty much all of the memory was allocated to read an HTTP response (presumably the file content from GCS):

Here's your code for posterity:

#include <vector>
#include <fstream>
#include <iostream>

int main(int argc, char** argv)
{
  std::vector<char> buf(4096);
  for (int i = 1; i < argc; ++i)
  {
    std::ifstream f(argv[i]);
    for (int j = 0; j < 32000; ++j)
      f.read(buf.data(), buf.size());
  }

  return 0;
}

And here's (some of) the GC log:

gc 18 @80.124s 0%: 0.014+7.7+0.011 ms clock, 0.014+0.30/2.4/0+0.011 ms cpu, 1261->1261->923 MB, 1292 MB goal, 1 P
fuse: 2017/05/19 14:13:37.265252 *fuseops.ReadFileOp error: fh.reader.ReadAt: startRead: NewReader: googleapi: got HTTP response code 503 with body: Backend Error
gc 19 @110.074s 0%: 0.011+6.3+0.011 ms clock, 0.011+0.37/3.1/0+0.011 ms cpu, 1815->1815->1327 MB, 1847 MB goal, 1 P
scvg0: inuse: 2575, idle: 0, sys: 2576, released: 0, consumed: 2576 (MB)
gc 20 @150.101s 0%: 0.009+96+0.035 ms clock, 0.009+1.4/23/5.3+0.035 ms cpu, 2590->2590->1888 MB, 2655 MB goal, 1 P
gc 21 @155.904s 0%: 0.006+0+8.2 ms clock, 0.006+1.4/23/5.3+8.2 ms cpu, 2065->2065->1958 MB, 2065 MB goal, 1 P (forced)
2017/05/19 14:14:44.121406 Wrote memory profile to /tmp/mem.pprof.
^C2017/05/19 14:15:51.733346 Received SIGINT, attempting to unmount...
2017/05/19 14:15:51.903228 Failed to unmount in response to SIGINT: fork/exec /bin/fusermount: cannot allocate memory
GC forced
gc 22 @283.915s 0%: 0.020+36+0.031 ms clock, 0.020+0/31/4.9+0.031 ms cpu, 2284->2284->2103 MB, 3916 MB goal, 1 P
scvg1: inuse: 2110, idle: 527, sys: 2638, released: 0, consumed: 2638 (MB)
GC forced
gc 23 @404.767s 0%: 0.017+3.4+0.008 ms clock, 0.017+0/3.4/0+0.008 ms cpu, 2103->2103->639 MB, 4206 MB goal, 1 P
GC forced
gc 24 @524.776s 0%: 0.015+2.3+3.3 ms clock, 0.015+0/2.3/0+3.3 ms cpu, 639->639->2 MB, 1279 MB goal, 1 P
scvg2: 201 MB released
scvg2: inuse: 7, idle: 2630, sys: 2638, released: 201, consumed: 2436 (MB)
gc 25 @565.564s 0%: 0.002+0+2.4 ms clock, 0.002+0/2.3/0+2.4 ms cpu, 2->2->2 MB, 2 MB goal, 1 P (forced)
2017/05/19 14:21:33.565370 Wrote memory profile to /tmp/mem.pprof.
2017/05/19 14:22:08.251682 Starting a garbage collection run.
2017/05/19 14:22:08.678957 Garbage collection succeeded after deleted 0 objects in 410.983438ms.
gc 26 @624.006s 0%: 0.004+0+2.6 ms clock, 0.004+0/2.3/0+2.6 ms cpu, 3->3->2 MB, 3 MB goal, 1 P (forced)
2017/05/19 14:22:32.008025 Wrote memory profile to /tmp/mem.pprof.
^C2017/05/19 14:22:59.400614 Received SIGINT, attempting to unmount...
gc 27 @651.636s 0%: 0.010+2.4+0.022 ms clock, 0.010+2.3/0/0+0.022 ms cpu, 5->5->3 MB, 6 MB goal, 1 P
2017/05/19 14:22:59.653737 Successfully unmounted in response to SIGINT.

Could you please try varying the GOGC environment variable (the default is 100, maybe try 10 or 50) and report what the result looks like?

[jacobsa]

I think I managed to reproduce this in a self-contained program, and have filed golang/go#20448 for what I consider a bug in Go's HTTP/2 library.

You can likely work around this by running gcsfuse with GODEBUG=http2client=0 in the environment, causing it to not use HTTP/2. Please confirm.

[jonathonl]

Disabling HTTP/2 does fix the memory issue, but another problem arises now when interleaving reads of many files. I've started getting a lot of dropped connections and CPU usage falls to virtually nothing.

fuse: 2017/05/23 14:28:23.114227 *fuseops.ReadFileOp error: fh.reader.ReadAt: readFull: read tcp 10.128.0.7:41284->173.194.74.95:443: read: connection reset by peer
fuse: 2017/05/23 14:28:23.114577 *fuseops.ReadFileOp error: fh.reader.ReadAt: readFull: read tcp 10.128.0.7:40642->74.125.126.95:443: read: connection reset by peer
fuse: 2017/05/23 14:28:23.114926 *fuseops.ReadFileOp error: fh.reader.ReadAt: readFull: read tcp 10.128.0.7:41288->173.194.74.95:443: read: connection reset by peer
fuse: 2017/05/23 14:28:23.115376 *fuseops.ReadFileOp error: fh.reader.ReadAt: readFull: read tcp 10.128.0.7:40646->74.125.126.95:443: read: connection reset by peer
fuse: 2017/05/23 14:28:23.115681 *fuseops.ReadFileOp error: fh.reader.ReadAt: readFull: read tcp 10.128.0.7:40648->74.125.126.95:443: read: connection reset by peer
fuse: 2017/05/23 14:28:23.116019 *fuseops.ReadFileOp error: fh.reader.ReadAt: readFull: read tcp 10.128.0.7:41294->173.194.74.95:443: read: connection reset by peer
fuse: 2017/05/23 14:28:23.116738 *fuseops.ReadFileOp error: fh.reader.ReadAt: readFull: read tcp 10.128.0.7:41298->173.194.74.95:443: read: connection reset by peer
fuse: 2017/05/23 14:28:23.117148 *fuseops.ReadFileOp error: fh.reader.ReadAt: readFull: read tcp 10.128.0.7:41300->173.194.74.95:443: read: connection reset by peer
...

This may be due to API rate limiting and the fact that my GCP project is heavily using resources right now. I will test again when things die down a bit.

[fdoumet]

Could this have to do with commit 284558bd039f4859a5fd4b465639fe69725e34a0? Doesn't seem like the issue was ever addressed:
golang/go#16656

[jacobsa]

As I said above I believe this was due to golang/go#20448 (therefore yes related to that commit), and should be fixed with the next release of Go. In the meantime you can disable http2 using GODEBUG=http2client=0. I haven't heard any definitive evidence that that doesn't work.

[jacobsa]

I will rebuild with go1.9rc2 in order to alleviate this problem.