[Core] Memory usage keeps going up over time

[joeriexelmans]

Burrow version: 0.23.1+2018-11-14T18:42:35Z (linux 64-bit binary from 'releases' page)
OS: Ubuntu 16.04.2 LTS

A 2-node setup was created, both burrow processes were running on the same machine. Then, for about 64 hours:

• Every 10 minutes, a batch of 50 contracts was deployed
• Every 5 minutes, 1 contract was deployed and 100 transactions were made to this contract (a setter function was called, which also emitted an event)
• Every minute, the CPU and memory usage of one of the burrow processes were logged as CSV data
• Every 5 minutes, the total size of the blockchain directory of one of the burrow processes was calculated and logged as CSV data
• Empty blocks enabled, one block every 1s

Disk & CPU seemed normal. Memory kept going up however, (up to 1 GB). Possibly a memory leak?

I've made some graphs...

(note: 'seconds' should be 'milliseconds' in those graphs)
raw_data.txt
contract.sol.txt

[silasdavis]

Thanks for this excellent report.

Just to pull in what I mentioned on rocket chat:

If you change Enabled = true in the burrow.toml in:

  [RPC.Profiler]
    Enabled = false
    ListenAddress = "tcp://127.0.0.1:6060"

then if you have Go installed once the memory is ramped up a bit run
go tool pprof -top http://localhost:6060/debug/pprof/heap

If you are able to do this I might be able to get to an understanding before spending a lot of time on reproduction.

[joeriexelmans]

OK a ran a new experiment, similar to the original one, but with all time intervals multiplied by 1/30. Because this time, I wasn't so much interested in whether the burrow processes would run without crashing for a long amount of time, I just wanted to reproduce the memory usage problem. So this time:

• Every 20 seconds, a batch of 50 contracts was deployed
• Every 10 seconds, 1 contract was deployed and 100 transactions were made to this contract (a setter function was called, which also emitted an event)
• Every 2 seconds, the CPU and memory usage of one of the burrow processes were logged as CSV data
• Every 10 seconds, the total size of the blockchain directory of one of the burrow processes was calculated and logged as CSV data
• Empty blocks (burrow setting) disabled

Again it was a setup with 2 validator burrow processes on the same machine: let's call them A and B. A was added as a persistent peer to B. So A was started first. This time only process B had very high memory usage, A seemed more stable at around 90 MB. (I don't know if during the original experiment, the memory usage was high for both processes or only for process B). All transactions were sent to the GRPC of process B.

The following is a graph showing CPU and memory usage of B:

As you can see, no more deployment transactions would 'complete' (from burrow.js perspective) after CPU usage of B hit 100% and memory usage was past 1 GB. So something went wrong there (too high load?). The application however kept sending deployment transactions all the way to the end, which could explain the further increase in memory usage.

Process B was configured to expose the memory profiler, here's the output all the way at the end:
pprof-output.txt

Here's the raw CSV data of CPU, memory, disk usage, number of deployed contracts and other transactions over time:
raw_data2.txt

The contract that was deployed was still the same as in the original experiment.

[joeriexelmans]

Ran the same experiment one more time, now only with half the load (time intervals * 1/15 instead of * 1/30). Again high memory usage in "process B".

Orange and blue reversed compared to last time (sorry for that)

Was able to run pprof before things got out of hand like they did last time: pprof-output2.txt

And again, the raw CSV data on which the graph is based: raw_data3.txt

[seanyoung]

@joeriexelmans thank you for that, graphs are very clear.
Are you able to able to post the scripts you used for your test? That will really help with out with our reproduction.
Thank you very much!

[joeriexelmans]

Here's the script (edited a little, moved all the hardcoded stuff to the top)
experiment.js.txt

Ran it again, this time monitoring the memory usage of both burrow processes. Also this time sent all transactions to process A instead of B. This time the memory usage of A was much higher, so it seems the process that gets sent the transactions has much higher memory usage. Memory usage of B also kept ever-increasing as you can see:

As you can see, I kept running it until no more transactions would complete (basically kept running it until things broke).

Also I'm sorry for the awful quality of the graphs, should probably use gnuplot instead of plot.ly but making graphs is not what I regularly do.

[joeriexelmans]

I put up a public repository with the experiment also. Contains scripts to start a single or 2-node setup. It will save you the trouble of manually filling in the PID values in the javascript file.
https://bitbucket.org/tmining/burrow-experiments

[joeriexelmans]

Added mem-usage.js script to the repo. I advice to run that script instead. It will wait for earlier batches of txs to complete before sending new batches, not overloading the burrow node, like it happened in some of my experiments above. The fact that a 2-node burrow setup breaks when sending too many transactions is a possibly different issue but not of interest here.

Also when I restart the burrow processes, memory usage is low again and goes up like before as I continue to send transactions. So probably just a memory leak.

[silasdavis]

@joeriexelmans what version of Go are you using?

[joeriexelmans]

For burrow itself it shouldn't matter because I used to released binary.
The pprof was done with go1.10.4.

[silasdavis]

I haven't been able to recreate the memory leak in the QueryParser that you saw. I have a hunch that it might be due to event subscriptions building up under load (we use event subscriptions to return the TxExecution during the BroadcastTxSync.

However, the fact we are query parsing at all is unnecessary and I have optimised this on develop with #974. @seanyoung is going to take a more careful look and reproduce what you are seeing - but if you have any time in the meantime could you have a go with latest develop and see if you see the issue.

One thing we have observed is the go runtime tends to be reserving quite a bit more memory than that which is shown on pprof heap. Some of this is likely to be down to caching, but not all.

Thanks for you effort on this, definitely in top spot for best issue of 2018 :)

[silasdavis]

Had another look over you graphs - and I think this all deserves a bit more reproduction but I had some additional thoughts:

You did three experiments:

1. Long-running, low load (deploys every 10 minutes)
2. Short-running, highest load (deploys every 20 seconds)
3. Short-running, medium load (deploys every 40 seconds)

Experiment 1 is the one I would most like to see the pprof output from - I wonder if you would be able to re-run it to see if the same behaviour occurs? The load is so low - much lower than we have test chains for I think that it i surprising to see this memory use

In 2 I believe the load saturated the CPU which caused subscriptions in our event system to mount up. This manifest as a very large allocation to Query (held here: https://github.com/hyperledger/burrow/blob/develop/event/pubsub/pubsub.go#L62) but under CPU saturation I believe the reason for it is failure to unsubscribe listeners, which is possilbe if the context on an unsubsribe times out or otherwise completes: https://github.com/hyperledger/burrow/blob/develop/event/pubsub/pubsub.go#L132 (note we handle the unsubscribe in a defer statement - https://github.com/hyperledger/burrow/blob/develop/execution/transactor.go#L90 though we do use the background context - so not entirely clear what this would lead to.

In any case I am fairly confident that the CPU saturation will be mostly down to logging, i.e. I notice you have set ExcludeTrace = false (which makes sense for debug I agree!) but this generates a large amount of logging and also by default does a certain amount of post-processing on the log output to give it nice formatting. Really their ought to be a health-warning onExcludeTrace = false - for production or performance testing this should be disabled. In experiment 2 you are still only doing 12.5 transactions per second. In my rather more adhoc testing (and in integration tests) I have seen Burrow comfortably handle 600+ tps with non-trivial contracts. Admittedly that tends to be more bursty. I think trace logging gets pretty ridiculous under high transaction load.

In experiment 3 we see heap allocation that is pretty much as expected. The system memory does grow - and this is something I have seen locally too - that system memory allocation is a significant multiple of heap allocation. There are a few possible reasons:

• We are leaking non-heap memory (i.e. stack) which will be a bit harder to debug (see runtime: pprof should report non-heap memory golang/go#15848)

• The Go runtime is hanging on to a lot of system memory that is has internally released to optimise its own allocations (it's not inconceivable Go is behaving badly in respect of some heuristic is uses for releasing memory - this is rather old so probably no longer applies but something like it might: https://stackoverflow.com/questions/16516189/why-total-mb-in-golang-heap-profile-is-less-than-res-in-top)

• Memory is just not getting GC'd quickly enough

It will be interesting to see a) what happens with ExcludeTrace = true and b) whether heap allocation tracks system allocation if we add some debug.FreeOSMemory() calls around the place.

There's probably a few other ways we could be a bit more graceful about what happens with event subscriptions under CPU saturation too.