Memory leak on go-ethereum 1.8.7

[vogelito]

System information

Geth version:

Geth
Version: 1.8.7-stable
Git Commit: 66432f3821badf24d526f2d9205f36c0543219de
Architecture: amd64
Protocol Versions: [63 62]
Network Id: 1
Go Version: go1.10
Operating System: linux
GOPATH=
GOROOT=/usr/local/go

OS & Version: Linux

Expected behaviour

Memory usage of go-ethereum should be stable.

Actual behaviour

Something happens which causes memory usage to increase substantially.

Steps to reproduce the behaviour

Unknown

pprof top

This wasn't hugely useful to us, but hoping it means something to the folks in here. Happy to provide additional information. This is currently happening ~1/day

# go tool pprof http://localhost:6060/debug/pprof/heap
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in /root/pprof/pprof.geth.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz
File: geth
Build ID: fb815f00e769fd84f7336a86cf929a66ba8ab66f
Type: inuse_space
Time: May 9, 2018 at 9:40pm (UTC)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 5332.62MB, 84.39% of 6318.78MB total
Dropped 349 nodes (cum <= 31.59MB)
Showing top 10 nodes out of 145
      flat  flat%   sum%        cum   cum%
 1186.93MB 18.78% 18.78%  1186.93MB 18.78%  runtime.malg
  861.97MB 13.64% 32.43%   861.97MB 13.64%  github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/util.(*BufferPool).Get
  708.04MB 11.21% 43.63%   708.04MB 11.21%  math/big.nat.setBytes
  529.06MB  8.37% 52.00%   529.06MB  8.37%  reflect.unsafe_New
  509.52MB  8.06% 60.07%  1251.55MB 19.81%  github.com/ethereum/go-ethereum/rlp.decodeBigInt
  453.14MB  7.17% 67.24%   464.65MB  7.35%  github.com/ethereum/go-ethereum/trie.(*hasher).store
     388MB  6.14% 73.38%      388MB  6.14%  github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/memdb.New
  264.43MB  4.18% 77.56%   264.43MB  4.18%  github.com/ethereum/go-ethereum/vendor/gopkg.in/fatih/set%2ev0.(*Set).Add
  228.51MB  3.62% 81.18%   482.26MB  7.63%  github.com/ethereum/go-ethereum/eth.(*peer).SendTransactions
  203.02MB  3.21% 84.39%   203.02MB  3.21%  github.com/ethereum/go-ethereum/event.(*Feed).Send

Metrics

Last month:

Last 2 months:

Additional info

For reference, this host was migrated to run:
v1.8.2 on March 5
v1.8.3 on March 27
v1.8.6 on Apr 26
v1.8.6 with PR #16576 on May 1
v1.8.7 on May 4

We run our node with the following cmd line arguments --rpc --rpcapi "debug,personal,eth,web3" --targetgaslimit 1000000 --cache 2048 --gpopercentile 30 --maxpeers 25

On May 1st we added --metrics --pprof --pprofaddr=127.0.0.1 and started tracking various metrics. We thought this was the source of the problem so earlier today we restarted the node without the additional flags, but unfortunately the memory leak happened again.

This is the memory breakdown the last 48 hours:

And since upgrading to 1.8.7:

[vogelito]

Note: geth is basically the only thing running on this box and we have made sure the memory increases in the box are all geth. The sawtooth shape in the memory graphs are geth restarts.

[corverroos]

We are experiencing a similar issue:

Geth started in docker container on Ubuntu with:

docker run \
    --memory=8g \
    -v /mnt/ethereum:/root/.ethereum \
    -p 8545:8545 \
    -p 30303:30303 \
    -p 6060:6060 \
    -d \
    ethereum/client-go:v1.8.7 \
    --pprof --pprofaddr=0.0.0.0 --rpc --rpcapi=eth,personal,txpool,debug,admin,net --rpcaddr=0.0.0.0 --cache=1024 --datadir=/root/.ethereum --gpopercentile=50 --syncmode=full --gcmode=archive --rpcvhosts=*

We introduced the 8GB memory limit as work around for docker to auto restart the container.

Output of memStats (time in UTC+2)

Output of /debug/pprof/heap at 2018-05-10 17:00 UTC+2:

Output of /debug/pprof/heap at 2018-05-11 02:00 UTC+2:

[vogelito]

We just downgraded to v1.8.6 with PR #16576. Will keep you posted

[mykolasmith]

+1, we are also experiencing this issue.

[vogelito]

Confirmed that 1.8.6 with PR #16576 also sees this issue. We're downgrading to 1.8.3 which is the last stable version we ran.

@ryanschneider suspects that the memory issues were always there (at least in 1.8.x) but have been exacerbated by the recent uptick in txs.

[mykolasmith]

@vogelito Just wondering, are you using filter queries? (experimental feature)

[vogelito]

@mykolasmith - no we are most definitely not.

[vogelito]

This is the node's memory consumption since Friday morning.

1.8.3 seems to be doing better, but if the issue is indeed caused by an uptick in txs, then it's possible things only look like this because it's the weekend.

[vogelito]

Update on memory usage. 1.8.3 still doing ok:

[vogelito]

@karalabe - I saw some memory-management related improvements on the latest v1.8.8 release
Do you think there's a chance they address the memory-related problems we're seeing here?

[karalabe]

Unfortunately not.

[karalabe]

@vogelito Out of curiosity. Could you try reverting #16494 locally for yourself from master and seeing if that fixes it. I don't see how it would, just playing guessing game as to what we've changed in 1.8.4 that might cause this.

[vogelito]

@karalabe - happy to. However, I was planning on waiting a bit more to see if the problem is indeed gone in 1.8.3

We ran 1.8.6 without problems for a while until there was an uptick in network transactions.

[karalabe]

Another interesting experiment might be to run 1.8.7 or 1.8.8 with --pprof, and when you see the memory spiking, load http://localhost:6060/memsize and generate a report (Scan "node"). This will use some experimental memory stats gathering written by @fjl to try and report how much memory different parts of our code use. That might help pinpoint what part is leaky.

[karalabe]

Do note however that 'scanning all objects and measuring their memory use' will probably hit the node hard for 30+ seconds. So, take care with doing this on a production system.