memory leak in PMX where Meter class retains object ExponentiallyMovingWeightedAverage and grows to substantial size (heapdump screens included)

[askhogan]

See screenshots. This is a continued and sharp rise in use over 8 hour period. The box has consistent processing flow.

The leak appears to be from the global include and extension of var Probe = require('./Probe.js');

See heapsnapshots. This is an 8 hour period of time.

[Unitech]

Thanks for inspecting,

https://github.com/keymetrics/pmx/blob/master/lib/utils/EWMA.js does not look to retain any reference

How do you know that it comes from EWMA?

[askhogan]

Thanks for followup. I know that it is PMX, because Meter is the retainer object. The retainer of Meter is the system / Context. So this is occurring from the require statement and not some custom probe I am applying.

Also, when I turn off pmx, the memory leak goes away.

[askhogan]

I can provide the heapdump snapshots to you, just pm me. Its a production box.

[email protected]

[jshkurti]

So, you aren't using any custom probes ?
This is just pmx running on default configuration ?

[askhogan]

Yes. No custom probes. I do have one action to take a heapdump. The other odd thing is keymetrics shows me more memory usage than the box has in total. See screenshot with 36GB

[Collaborator Edit] => removed screenshot link because it contains your keys

[askhogan]

[askhogan]

Thanks for the remove. Didn't know keys were in there. Let me know if I need to post again or if you were able to get. I trashed mine so will probably have to recreate. The jist was keymetrics added up to 36GB, but my box only has 30GB total.

I know you guys are swamped. I am more than happy to help or provide more testing. I love PM2. We are beginning to rely on it heavily. Just point me in the right direction.

[askhogan]

I did more testing on this using node-inspector. I can reproduce the leak each time. I was able to resolve the leak by adding pmx to my client library and setting the below options.

require('pmx').init({
http : false, // (Default: true)
errors : false,
custom_probes : false,
network : false, // Traffic usage monitoring
ports : false // Shows which ports your app is listening on
});

I bet the leak is likely on http, however, I disabled for all of them. I will update once I have more time to narrow it down.

[jshkurti]

Hey, can you tell for sure if it's http or custom_probes or errors ? (These are the only flags true by default, network and ports are false by default).
I also think it's http thought but just to be sure.

And can you try with [email protected] ? I changed a bit the way how http is overloaded but I can't tell for sure if it fixes the memory leak.

Thanks again for your contribution :)

[askhogan]

It's for sure http. I have some more node inspector dumps. I think it
doesn't back off or batch enough under high load. This box I have is a
message processor. Long running and a hundred thousand + messages. All
outbound connections.

I tried to see where to edit but didn't have enough time. New relic has
some good batching code in their node SDKs for reference.

On Tuesday, May 26, 2015, Joni Shkurti [email protected] wrote:

Hey, can you tell for sure if it's http or custom_probes or errors ?
(These are the only flags true by default, network and ports are false by
default).
I also think it's http thought but just to be sure.

And can you try with [email protected] ? I changed a bit the way how http is
overloaded but I can't tell for sure if it fixes the memory leak.

—
Reply to this email directly or view it on GitHub
#23 (comment).

[askhogan]

Will give it a shot later today with new version.

On Tuesday, May 26, 2015, Patrick Hogan [email protected] wrote:

It's for sure http. I have some more node inspector dumps. I think it
doesn't back off or batch enough under high load. This box I have is a
message processor. Long running and a hundred thousand + messages. All
outbound connections.

I tried to see where to edit but didn't have enough time. New relic has
some good batching code in their node SDKs for reference.

On Tuesday, May 26, 2015, Joni Shkurti <[email protected]
javascript:_e(%7B%7D,'cvml','[email protected]');> wrote:

Hey, can you tell for sure if it's http or custom_probes or errors ?
(These are the only flags true by default, network and ports are false by
default).
I also think it's http thought but just to be sure.

And can you try with [email protected] ? I changed a bit the way how http is
overloaded but I can't tell for sure if it fixes the memory leak.

—
Reply to this email directly or view it on GitHub
#23 (comment).

[jshkurti]

I've been testing a bit with this sample code :

var pmx = require('pmx').init({
  network: true,
  ports: true
});

var http = require('http');

setInterval(function keepAlive() {
  global.gc();
}, 500);

http.createServer(function(req, res) {
  res.end('hello world');
}).listen(8080);

(launch it with --node-args="--expose-gc")

And I flooded the server with requests via ab -c 200 -n 1000000 localhost:8080/

I wasn't able to reproduce the memory leak :/
Memory usage stabilized at around ~50MB and never went above that.

[jshkurti]

Can you give me a sample code which triggers the leak please ?

[askhogan]

Sure. It relies on some internal dependencies. Give me some time to clean it up.

Did you use node .12.x?
What version of pmx did you use? I was on 0.3.11 when I ran that

Environmentally the first screenshots (7 days ago) I gave you that started this ticket were in production. I was running pm2 cluster and no pmx inside. I was able to get rid of the memory increase by setting pmx.init({http: false}) inside of my production code. Can you explain a little bit more how pm2 and pmx interact? It looks to me from the code that pm2 has default options to communicate with keymetrics if pmx is not defined and then (if) pmx is included it will send an rpc command to pm2 to modify those default options.

The second screenshots (2 days ago) I gave you were running through node-inspector so I wasn't able to run through pm2. I explicitly set options via pmx to imitate what pm2 would do.

I just want to make sure I am comparing apples to apples. Will code that is not using pm2, and just using pmx act the same as a code that is being run by pm2 (after keymetrics initialization)?

[jshkurti]

pmx is injected automatically when an app is launched in cluster mode with default options https://github.com/keymetrics/pmx/blob/master/lib/index.js#L32-L42

Did you use a framework like express, koa, sails ?
Because i ran my tests with a basic http server and weren't able to make it leak.

[jshkurti]

I used [email protected] and [email protected]

[jshkurti]

I used this sample : https://github.com/jshkurti/benchmark

[jshkurti]

I did 3 heapsnapshots within 1 hour interval each.
The Meter object stayed still :

[jshkurti]

Can you give it a try with [email protected] please ? :)

[jshkurti]

And/or give us a sample code which triggers the leak.

[jshkurti]

@askhogan :)

[askhogan]

Sorry man. I got swamped over the last few days. I will try this, this week.

[jshkurti]

Thanks :D

[askhogan]

Installed 0.3.16

New settings

require('pmx').init({
http: true,
errors: true,
custom_probes: false,
network: true,
ports: true
});

You can look at my metrics in keymetrics to see difference. With all of it off over the last few weeks memory usage has been stable at around 2.4GB.

[askhogan]

I hope it levels out, but you can see once its on, it just goes up.

[askhogan]

Grew from consistent 2.4GB mem usage with pmx off to now 7GB (< 200MB -> around 500MB per worker) in a few hours with it on. The only code change was the additions I noted above. I gotta shut this off for now and just use keymetrics without the http tracking turned on (still super awesome without this on BTW!!). This server processes lots and lots of messages. When the heap gets big the garbage collection starts eating a lot of CPU and I get weird latency on batches of messages.

I know you are having trouble re-creating it. Let me know how I can help.

[askhogan]

Pause on my comments for a bit. I just realized the npm module didn't update. Really weird. Let me re-test. That was all done on .3.11

[askhogan]

I had a local version at .3.11 and a global version inside pm2 at .3.16.... I updated the global pm2 version earlier. I now just updated the local version as well. Re-testing...

[askhogan]

Same issue. I had to turn off http.

[Unitech]

Thanks for reporting,

We have some questions:

• Which Node.js version do you use?
• Which Node.js modules do you use? (if we could get a copy of your dependencies it would be helpful)
• Do you use NewRelic in the same time?
• Are you doing anything uncommon with the HTTP?

If you find the time, the best would be to have small subset of your application to reproduce the leak ourselves.

Thanks!
Best,
Alex

[jshkurti]

Unitech/pm2#1453 (comment)

Hi @askhogan :)
Update : it seems this is related to Sails. Were you using Sails anywhere in your app ?

[askhogan]

No Sails. I did have express, which Sails is based on.

[danruehle]

I am experiencing the same issue. Using PM2 to run express web server in NodeJS 0.12.7, PM2 0.14.7, express 4.12.4. When running in fork mode, there is no memory leak. When running in cluster mode, this same memory leak is seen. I don't use keyketrics for monitoring, so we are now using the --no-pmx flag and that fixes the issue.

[andreafdaf]

Same issue here. I'm running a queue worker using aws-sqs, the code runs fine without pmx, memory is stable. When pmx has:

http: true

memory keeps rising.

Inbound connections seems to be less of a problem, outbound connections create more problems. Also in my heapdumps I find a lot of (really smallweight) references to TLSWrap, TLSSocket, clearTimeout and other connection related stuff. It's like the http functionality is holding some data that stays hanging and don't get garbage collected.

I've tested with a minimal setup that simply iterates over some empty queues and memory keeps rising nonetheless. Tested on:

• nodejs: 5.12.0 and 6.5.0
• pmx: 0.6.4

[vmarchaud]

@andreafdaf Can you share with us your minimal setup that show this leak ?

[andreafdaf]

@vmarchaud I can create a github repo if you want, is it ok? I can work on it in the next couple of days, the files I'm using contain some private/corporate data so they cannot be shared directly.

With a minimal setup memory grows veeery slowly but it's noticeable after a few hours.

An example of minimal setup can be something like that:

require('pmx').init({
  http: true,
  errors: true,
  network: true,
})

const AWS = require('aws-sdk')

const sqsReceiveParams = {
  QueueUrl: "queue-url-goes-here",
  MessageAttributeNames: ['All'],
  WaitTimeSeconds: 1,
}

function manageMessageQueue() {
  const sqs = new AWS.SQS({ config-object })
  sqs.receiveMessage(sqsReceiveParams)
    .promise()
    .then(checkMessages) // it doesn't matter what this function does, can be a no-op
    .catch(logError)

  setTimeout(manageMessageQueue, 1000)
}
manageMessageQueue()

[vmarchaud]

@andreafdaf I understood that you had a way to reproduce a fast memory leak, but if its just a simple as your example i will try to start an application and let it run over days to look for memory leak.

[andreafdaf]

@vmarchaud if you want it to grow faster just set the timeout to 100 and wait a bit, the behavior is noticeable even after 10 mins. After a while GC starts eating the CPU even with such a minimal setup.

[14011:0x1b6bc40]        5 ms: Scavenge 2.2 (37.1) -> 2.2 (37.1) MB, 0.6 / 0 ms [allocation failure].
[14011:0x1b6bc40]        9 ms: Scavenge 2.3 (38.1) -> 2.2 (39.1) MB, 0.6 / 0 ms [allocation failure].
[14011:0x1b6bc40]       55 ms: Scavenge 4.1 (41.1) -> 3.7 (41.1) MB, 0.6 / 0 ms [allocation failure].
[14011:0x1b6bc40]       98 ms: Scavenge 5.8 (41.1) -> 4.8 (42.1) MB, 1.1 / 0 ms [allocation failure].
[14011:0x1b6bc40]      129 ms: Scavenge 6.8 (42.1) -> 5.5 (42.1) MB, 1.4 / 0 ms [allocation failure].
[14011:0x1b6bc40]      165 ms: Scavenge 7.7 (43.1) -> 6.6 (43.1) MB, 1.3 / 0 ms [allocation failure].
[14011:0x1b6bc40]     1928 ms: Scavenge 12.5 (46.1) -> 10.2 (47.1) MB, 2.1 / 0 ms [allocation failure].
[14011:0x1b6bc40]     3289 ms: Scavenge 14.0 (47.1) -> 11.5 (48.1) MB, 2.5 / 0 ms [allocation failure].
[14011:0x1b6bc40]     5374 ms: Scavenge 15.3 (49.1) -> 12.2 (49.1) MB, 1.6 / 0 ms [allocation failure].
[14011:0x1b6bc40]     7467 ms: Scavenge 16.1 (49.1) -> 13.0 (50.1) MB, 2.5 / 0 ms [allocation failure].
[14011:0x1b6bc40]    11922 ms: Scavenge 20.7 (50.1) -> 14.2 (50.1) MB, 3.1 / 0 ms (+ 10.7 ms in 113 steps since last GC) [allocation failure].
[14011:0x1b6bc40]    13782 ms: Mark-sweep 17.4 (50.1) -> 11.2 (50.1) MB, 5.2 / 0 ms (+ 15.0 ms in 159 steps since start of marking, biggest step 0.2 ms) [GC interrupt] [GC in old space requested].
[14011:0x1b6bc40]    18263 ms: Scavenge 19.3 (51.1) -> 12.8 (51.1) MB, 2.9 / 0 ms [allocation failure].
[14011:0x1b6bc40]    22539 ms: Scavenge 20.4 (51.1) -> 14.3 (52.1) MB, 3.5 / 0 ms (+ 9.0 ms in 90 steps since last GC) [allocation failure].
[14011:0x1b6bc40]    25737 ms: Mark-sweep 19.7 (52.1) -> 12.2 (52.1) MB, 7.2 / 0 ms (+ 16.7 ms in 171 steps since start of marking, biggest step 0.3 ms) [GC interrupt] [GC in old space requested].
[14011:0x1b6bc40]    30100 ms: Scavenge 20.1 (54.1) -> 13.7 (54.1) MB, 3.7 / 0 ms (+ 9.7 ms in 93 steps since last GC) [allocation failure].
[14011:0x1b6bc40]    33325 ms: Mark-sweep 19.1 (54.1) -> 12.4 (50.1) MB, 16.3 / 0 ms (+ 17.3 ms in 173 steps since start of marking, biggest step 0.2 ms) [GC interrupt] [GC in old space requested].
[14011:0x1b6bc40]    40530 ms: Mark-sweep 24.8 (50.1) -> 12.6 (50.1) MB, 9.4 / 1 ms (+ 16.9 ms in 163 steps since start of marking, biggest step 0.3 ms) [GC interrupt] [GC in old space requested].
[14011:0x1b6bc40]    49368 ms: Scavenge 27.8 (52.1) -> 15.2 (53.1) MB, 7.6 / 1 ms [allocation failure].
[14011:0x1b6bc40]    58161 ms: Scavenge 29.6 (53.1) -> 17.1 (55.1) MB, 6.1 / 1 ms [allocation failure].
[14011:0x1b6bc40]    66988 ms: Scavenge 31.7 (55.1) -> 19.2 (57.1) MB, 6.3 / 1 ms [allocation failure].
[14011:0x1b6bc40]    75876 ms: Scavenge 33.9 (57.1) -> 21.3 (59.1) MB, 5.6 / 1 ms [allocation failure].
[14011:0x1b6bc40]    83524 ms: Mark-sweep 34.3 (59.1) -> 13.7 (59.1) MB, 9.8 / 2 ms (+ 17.7 ms in 185 steps since start of marking, biggest step 0.2 ms) [GC interrupt] [GC in old space requested].
[14011:0x1b6bc40]    92405 ms: Scavenge 28.9 (60.1) -> 16.1 (61.1) MB, 7.4 / 1 ms (+ 8.9 ms in 91 steps since last GC) [allocation failure].
[14011:0x1b6bc40]    96335 ms: Mark-sweep 22.5 (61.1) -> 13.3 (51.1) MB, 13.7 / 0 ms (+ 18.2 ms in 186 steps since start of marking, biggest step 0.3 ms) [GC interrupt] [GC in old space requested].
[14011:0x1b6bc40]   104726 ms: Mark-sweep 27.7 (51.1) -> 14.6 (51.1) MB, 10.3 / 1 ms (+ 17.6 ms in 191 steps since start of marking, biggest step 0.3 ms) [GC interrupt] [GC in old space requested].
[14011:0x1b6bc40]   113470 ms: Scavenge 28.9 (52.1) -> 16.4 (53.1) MB, 7.1 / 1 ms [allocation failure].
[14011:0x1b6bc40]   122443 ms: Scavenge 30.7 (53.1) -> 18.3 (55.1) MB, 5.9 / 1 ms [allocation failure].
[14011:0x1b6bc40]   131099 ms: Scavenge 32.7 (55.1) -> 20.2 (57.1) MB, 5.9 / 1 ms [allocation failure].
[14011:0x1b6bc40]   140007 ms: Scavenge 34.7 (57.1) -> 22.1 (59.1) MB, 9.2 / 1 ms [allocation failure].
[14011:0x1b6bc40]   148978 ms: Scavenge 36.5 (59.1) -> 24.0 (61.1) MB, 6.0 / 1 ms [allocation failure].
[14011:0x1b6bc40]   157377 ms: Mark-sweep 38.1 (61.1) -> 15.2 (61.1) MB, 11.1 / 2 ms (+ 19.4 ms in 204 steps since start of marking, biggest step 0.2 ms) [GC interrupt] [GC in old space requested].
[14011:0x1b6bc40]   166371 ms: Scavenge 30.3 (62.1) -> 17.6 (63.1) MB, 7.5 / 1 ms (+ 8.3 ms in 91 steps since last GC) [allocation failure].
[14011:0x1b6bc40]   171066 ms: Mark-sweep 25.4 (63.1) -> 14.8 (52.1) MB, 10.9 / 1 ms (+ 20.6 ms in 206 steps since start of marking, biggest step 0.4 ms) [GC interrupt] [GC in old space requested].
[14011:0x1b6bc40]   180357 ms: Scavenge 30.5 (53.1) -> 17.3 (53.1) MB, 6.0 / 1 ms (+ 20.8 ms in 210 steps since last GC) [allocation failure].
[14011:0x1b6bc40]   180455 ms: Mark-sweep 17.5 (53.1) -> 14.8 (54.1) MB, 6.9 / 0 ms (+ 21.0 ms in 213 steps since start of marking, biggest step 0.7 ms) [GC interrupt] [GC in old space requested].
[14011:0x1b6bc40]   190307 ms: Scavenge 31.0 (54.1) -> 17.2 (54.1) MB, 5.5 / 1 ms [allocation failure].
[14011:0x1b6bc40]   199050 ms: Scavenge 31.4 (54.1) -> 19.0 (56.1) MB, 6.0 / 1 ms [allocation failure].
[14011:0x1b6bc40]   208011 ms: Scavenge 33.5 (56.1) -> 20.9 (57.1) MB, 6.1 / 1 ms [allocation failure].

and then it goes on and on and on (this is just a sample, GC recovers some memory every turn but not enough and overall it grows to infinity)

[satazor]

Just wanted to give you guys an heads up: I'm also experiencing a memory leak on https://npms.io/ 's analyzer that has a scoring process that runs continuously and does a lot of HTTP requests (to couchdb and elasticsearch).

After just 10m running the analyzer's scoring, it ends up with ~2GB of ram and eventually crashes with out of memory. Disabling pmx fixes the problem but I really liked the pmx integration with keymetrics. :/

[vmarchaud]

@satazor Thanks for the report, could you come over http://slack.pm2.io to discuss about this ?

[satazor]

An update regarding my previous comment: I and @vmarchaud went together on a small journey to understand the leak and we come to the following conclusion: I had a subtle leak on my code that was being "augmented" by pmx due to their error wrapping.

I'm using bluebird with long stack traces enabled which, after looking at bluebird's code, creates a lot of Error objects to keep track of the promises stack (even if a promises resolve successfully). All those error objects were being handled by pmx which in turn generated more memory. The leak was already there, but pmx made it more evident because of how it interoperates with bluebird.

Thanks @vmarchaud and hope that my findings help someone.

[ATGardner]

I am not sure if this is related to the leak, but it is something in the http monitoring -
I've been playing around with some simple metrics at home, and I noticed that the default http metrics stopped working for me in keymetrics (it always shows "0").
I tried debugging the pmx code, and I noticed that the SimpleHttpWrap code is being called 5 times, on a single "require('express')" call. That creates 5 gl_meter objects, only the last of which gets it value marked. I suspect that due to some race, sometimes this is not the metric that is being sent to keymetrics, so the dashboard just shows "0" value all the time.
Also - there seems to be some mix up between the global pmx module (under ~\AppData\Roaming\npm\node_modules\pm2\node_modules\pmx), and the local one (under node_modules\pmx) - out of the 5 times the SimpleHttpWrap code is called, the first 4 are from the global node_modules, and the last one is from the local one.

[dreaganluna]

Did you even find anything for @andreafdaf's example? You said you would look into it, but the conversation fell flat right after that post...
I have come to a point where my superior is asking me to simply remove "that lib that causes the memory leaks", which sucks, because I like the extra info it provides.

[dreaganluna]

no response? are you implying I should remove pmx..?

[andreafdaf]

@dreaganluna I'm exactly in your same situation and had to remove HTTP monitoring

[pk-pranshu]

I have the same issue. For me as well the code runs fine without pmx, memory is stable. But with pmx with http:true it just keeps on increasing.

pmx settings used:

require('pmx').init({
     transactions: true,
     http: true
});

Versions :-
nodejs: v7.10.0
pmx: 1.2.0

Any updates on this open issue will help. @Unitech @askhogan

[glortho]

We had to remove pmx because of memory leaks. With our server under load it was retaining hundreds of thousands of stack traces (and maybe other strings?) in memory, each at 2k or so.

Incidentally, their heap snapshotting tool also doesn't work reliably from the UI and fails via the CLI on modern versions of node. At this stage I can't be sure that their heap snapshotting tool doesn't have a memory leak itself. A carnival funhouse!

Support told me that they were aware of the problem and planned to fix it sometime in the uncertain future.

Given their lack of response/fix here to a critical issue (and to lots of other issues we've raised over the last few years), well...

Abandon hope all ye who enter here

[jodevsa]

We encountered the same problem. Our API's run on limited resources and after 1 week from each time we restart them, our service starts becoming really slow with a huge increase in CPU/mem usage.

heap snapshots while running locally ( take a look at the #Delta's of the first picture) :

pmx: v1.6.7

pmx config:

{
      custom_probes : true, 
      network       : true, 
      ports         : true  
  }