Node: is heapUsed a useful metric?

[lloydbenson]

I am trying to understand when doing a process.memoryUsage() what the heapUsed metric is. I had originally thought this would always be number smaller than heapTotal and would tell me of the allocated heap, what the actual active heap being used was. This doesn't appear to be the case. I don't have a simple case boiled down to show this, but when tracking this over time I have gotten results like this when looking at rss, heapTotal, and heapUsed.

54 mb rss, 44 mb heaptotal, 4699 mb heapUsed

I was worried at first I had a leak, but the app seems just fine and heapTotal is staying just where I expect and I haven't run into any crashes or anything like that. It behaves more like uptime where heapUsed is really the total heap I've ever used. As I understand it from the doc, this is just reporting whatever v8 says it is. It didn't really seem to matter what version of node I used, though for this case I am using 4.1.0.

I looked around for a while to try to make sense of this metric and I am coming to the conclusion that heapTotal is really the metric that is meaningful but I wanted to reach out to make sure I am not missing something or if someone has a good link to a better explanation of what this metric does.

[mscdex]

Can you provide a reproducible example that shows this?

[lloydbenson]

As I mentioned in the thread I don't have a simple use case yet. I am not even sure there is a problem. As I mentioned in the issue, this is simply a question of what it is supposed to be. If this is unexpected and should never happen, then I can proceed with trying to come up with a reproducible case. Is that the case and should it always be lower than heapTotal? I don't quite see since this is strictly part of v8 how this could even be solved. I am merely trying to understand if its a useful metric to even consider.

[bnoordhuis]

@lloydbenson Can you try checking what console.log(require('v8').getHeapStatistics()) prints under those circumstances?

[lloydbenson]

@bnoordhuis Thanks for the reply. I will try that out and get back to you. Are you only interested in used heap over the max of ~1.5 gigs or just any general heapUsed > heapTotal?

[bnoordhuis]

Anytime used > total.

[lloydbenson]

process.memoryUsage(): 120 mb rss, 68 mb heaptotal, 145 mb heapUsed

v8 statistics: 68 mb v8 heaptotal, 7 mb v8 heaptotalexec, 43 mb v8 physize 1367 mb v8 totalavail, 145 mb v8 usedheap, 1464 mb heaplimit

[bnoordhuis]

Can you post the output of the console.log statement? It's a little easier for me to work with.

[lloydbenson]

Yes, sorry. Will do that shortly.

[lloydbenson]

{ total_heap_size: 69109760,
total_heap_size_executable: 7340032,
total_physical_size: 42765112,
total_available_size: 1435240728,
used_heap_size: 79085992,
heap_size_limit: 1535115264 }

[bnoordhuis]

Thanks. Curious, I wonder if it's a V8 accounting error. Does it also happen when you start node with --noconcurrent_sweeping?

[lloydbenson]

{ total_heap_size: 100110592,
total_heap_size_executable: 7340032,
total_physical_size: 62696168,
total_available_size: 1416882056,
used_heap_size: 106421368,
heap_size_limit: 1535115264 }

even after adding that flag to node startup.

[bnoordhuis]

My working hypothesis is that V8 is overestimating the live objects but I have no way to verify that. If you can put a test case together somehow, that would help immensely.

[lloydbenson]

Thanks for the info. I will try to boil this down into a simple use case but that may take a while. If its easier, feel free to close this up and I can re-open it.

[smartmouse]

Hi. just interested to know what os and arch are you using? Are you using a VM or a real physical machine?

[lloydbenson]

It is an ultrabook running fedora 21 x64. The app is mostly doing alot of calls to an API service (thats local to the same machine) with somewhat large payloads (output of test commands e.g. the make output of nodejs compilation). The API service mostly just does child spawn processes and writes that data to file and I fetch that data via the API to the app. It does talk via wireless to github (which may be flakey).

Mostly I was just wondering what conditions this was possible or if it was something to even worry about to track down. I still do not fully understand if there is a problem so its hard to narrow down the use case. I was first going to try a use case in the framework with a large payload and then try to further this my then reducing it away from the framework into http calls.

[stevenk15]

I am also experiencing this behavior with an app that I am working on. HeapUsed just continues to grow. The output of process.memoryUsage() from earlier today shows this:

memoryUsage: {
      rss: 94019584,
      heapTotal: 55873632,
      heapUsed: 3193887952
    }

Since then it has gone past 3.5GB. I just restarted the app with the --noconcurrent_sweep flag set. I'm assuming that this is not the expected behavior and that heapUsed should probably be a number that is less that heapTotal and/or rss???

My app is running Node 4.2.4 on Ubuntu 12.04.

[bnoordhuis]

heapUsed should be less than heapTotal, yes. It doesn't have to be less than rss.

Is your node binary 32 or 64 bits? node -p process.arch will tell you.

[stevenk15]

Its 64.

My tests take some time before you can clearly see the heapUsed increase. Like I mentioned above, I'm running it now with the --noconcurrent_sweeping flag set. I'll provide an update if I see an improvement using this.

[aahoughton]

For what it's worth, we're seeing the same (on 4.2.4, 64 bit). The OS (ubuntu trusty, 64bit) disagrees in re: memory used. It doesn't happen immediately for us, I don't know why it happens, but it _always_ happens.

[stevenk15]

The heapUsed value is continuing to climb even with the --noconcurrent_sweeping flag set. It has not hit the 1.5GB threshold yet but it will very soon.

[bnoordhuis]

Is there a way for me to reproduce locally? Preferably without using lots of third-party modules.

[stevenk15]

We have not had much luck reproducing it locally until very recently and we've been wrestling with a memory leak bug for several weeks. The reliability of this figure, which we had been using as the gauge to our success or failure, is now complicating our efforts.

We see it daily on our production environment which takes a fair amount of traffic, about 10 - 20 requests per second. We did not see it in our other environments until we started throwing a lot of traffic at it using siege. Currently we have 3 separate siege processes running with concurrencies at 10, 15, and 25, non-benchmark mode, using a random list of 1000s of urls.

The app itself is a restify app (version 4.0.3) that acts as a proxy to another service. It performs some minor modifications to the payload that the other service returns, and then returns that payload to the client. Its running on Ubuntu 12.04 using node 4.2.4.

I've created a simple restify app doing a similar set of operations and I'm currently testing that on my mac and another Ubuntu 12.04 machine to see if I can get it to reproduce the behavior. It takes a long time to clearly determine if the heapUsed figure is growing in the manner we see. I'll update this thread with anything I learn.

[stevenk15]

Unfortunately, I've not been able to reproduce locally. I tried a few different things including sieging for several days against a bare bones application. However, this is definitely happening on some of our other environments, especially the ones under heavy load.

Below you can see it cross over the 2GB mark. I've seen it go over 3.5GB. Not sure what else to do other than ignore this number.

[matthiasg]

i also have some issues understand the exact meaning of memoryUsage. I am building an ES6 Map with 10.000.000 objects with a small test program (to understand lookup times and memory usage with large Maps).

The memoryUsage() before and after building the map for example is:

before ram { rss:   17891328, heapTotal:    9587968, heapUsed:    4571688 }
after ram  { rss: 3314794496, heapTotal: 2277003008, heapUsed: 2242484528 }

So heapUsed and heapTotal are a lot smaller than rss. So what else is in rss consuming a GiB of RAM but is not in the heap ?

I also ran the test with getHeapStatistics()

before ram { rss: 17850368, heapTotal: 9587968, heapUsed: 4572416 }
{ total_heap_size: 10619904,
  total_heap_size_executable: 5242880,
  total_physical_size: 10619904,
  total_available_size: 1415054528,
  used_heap_size: 6053776,
  heap_size_limit: 1459617792 }

after map ram { rss: 3314737152, heapTotal: 2277003008, heapUsed: 2242506000 }
{ total_heap_size: 2277003008,
  total_heap_size_executable: 5242880,
  total_physical_size: 2277003008,
  total_available_size: 3459953072,
  used_heap_size: 2242606064,
  heap_size_limit: 1459617792 }

Note: I ran global.gc() after building the Map and before printing the after information

[stevenk15]

We seem to have gotten around this issue completely by using streams appropriately in our app. Our app was calling out to another service and we were loading the entire response into memory to then do manipulations on that response. These responses were quite large in some cases and I believe that they were being stored in the large object space which never gets garbage collected. Now we are reading the response as a stream and this has reduced our memory footprint significantly. Hope this helps anyone with a similar issue.

[bnoordhuis]

I'll close this out because there's been no real activity in > 6 months and I've not been able to reproduce myself but it's possible it was caused by V8 using 32 bits integers in places where it should have been using 64 bits integers.

If anyone knows of a good way to reproduce with a current release, let me know and I'll reopen.