Memory Leak on Subscription (Windows) #500

nirbenda · 2019-02-27T09:27:29Z

Hello,

I am experiencing what seems to be a memory leak.
At first the NodeJS process memory is ~40MB and after about 5-10 minutes (of continiuosly receiving messages every two seconds and acking them) it rapidly grows from 40MB to 1.6GB in term of seconds, and after a few minutes Node crashes with OOM because it excceeded the maximum capacity allowed for memory allocation.
Inspecting the allocations points to the promisify and JSBufferArray allocations.
I might be doing something wrong, but this code was taken from the examples (only that the listener timeout was removed).

Help would me much appreciated.

Thanks,
Nir

Environment details

OS: Windows 10
Node.js version: v8.10.0
npm version: 6.8.0
@google-cloud/pubsub version: 0.25.0

Steps to reproduce

Publish to a topic once in two seconds using external service ( I use python for this for example )
Run a subscription listener service, such as this for NodeJS:


var http = require('http');
async function listenForErrors(subscriptionName) {
  const {PubSub} = require('@google-cloud/pubsub');
  const pubsub = new PubSub();
  const subscription = pubsub.subscription(subscriptionName);

  const messageHandler = function(message) {
    console.log('got a message ');
    message.ack();
  };

  subscription.on(`message`, messageHandler);
}
listenForErrors("my-sub")
 
//create a server object:
http.createServer(function (req, res) {
  res.write('Hello World!'); //write a response to the client
  res.end(); //end the response
}).listen(8080); //the server object listens on port 8080

The text was updated successfully, but these errors were encountered:

callmehiphop · 2019-02-27T09:39:34Z

Hi @nirbenda, do you know approximately how many messages you have waiting to be processed? If you're only getting 1 every 2 seconds that would mean over the course of 10 minutes you've only processed about 300 messages.

nirbenda · 2019-02-27T10:10:15Z

Hi @callmehiphop , thanks for looking into this.
Yes, as it is a message every 2 seconds and it takes about 5 minutes to happen so it is about 150-300 messages being processed.

callmehiphop · 2019-02-27T10:27:37Z

I guess what I'm trying to get at is if your application is expecting about 30 messages per minute. One possible cause of a memory leak could be the clients flow control mechanisms not functioning properly, but in this case that seems unlikely given the low number of pending messages.

nirbenda · 2019-02-27T10:32:00Z

After a while I get this heap out of memory message:


<--- Last few GCs --->

[10224:000002CE21274B00]  1212560 ms: Mark-sweep 1849.2 (1976.9) -> 1849.2 (1945.9) MB, 2901.2 / 1.2 ms  last resort GC in old space requested
[10224:000002CE21274B00]  1215427 ms: Mark-sweep 1849.2 (1945.9) -> 1849.2 (1945.9) MB, 2866.6 / 1.6 ms  last resort GC in old space requested


<--- JS stacktrace --->

==== JS stack trace =========================================

Security context: 000000B109EA57C1 <JSObject>
    2: /* anonymous */(aka /* anonymous */) [H:\ReteAI\tmp\node_modules\@google-cloud\pubsub\build\src\subscriber.js:22] [bytecode=0000024CC02AECF9 offset=75](this=000003EC16E822D1 <undefined>,resolve=000001CD103DE3B9 <JSFunction (sfi = 000003EC16EACD21)>,reject=000001CD103DE401 <JSFunction (sfi = 000003EC16EACE81)>)
    3: new Promise(aka Promise)(this=000003EC16E82311 <the_hole>,000001CD103D...

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
 1: node_module_register
 2: v8::internal::FatalProcessOutOfMemory
 3: v8::internal::FatalProcessOutOfMemory
 4: v8::internal::Factory::NewUninitializedFixedArray
 5: v8::internal::JSReceiver::GetOwnPropertyDescriptor
 6: v8::internal::JSReceiver::GetOwnPropertyDescriptor
 7: v8::internal::StringHasher::ComputeUtf8Hash
 8: v8::internal::StringHasher::ComputeUtf8Hash
 9: v8::internal::operator<<
10: v8::internal::operator<<
11: v8::internal::operator<<
12: v8::internal::operator<<
13: v8::internal::operator<<
14: v8::internal::operator<<
15: 0000039A71D843C1

callmehiphop · 2019-02-27T12:23:27Z

@nirbenda so far I haven't been able to reproduce the issue you're seeing. I thought maybe it was specific to Windows, but my PC runs your reproduction code well enough and memory seems to sit around 60MB on my machine.

I'm running the following publisher script at the same time to try and emulate getting 1 message every 2 seconds.

const {PubSub} = require('@google-cloud/pubsub');
const pubsub = new PubSub();

const topic = pubsub.topic('my-topic', {
  batching: {maxMilliseconds: 0}
});

const message = Buffer.from('Hello, world!');

setInterval(() => topic.publish(message), 2000);

Is there anything I could do differently that would give me the errors you're seeing?

nirbenda · 2019-02-27T13:19:00Z

Maybe some of the inner dependency versions? Maybe legacy installed packaged are causing this.
I got many deduped libraries, maybe you can find a problem here?
Here is the 'npm list':


-- @google-cloud/[email protected]
  +-- @google-cloud/[email protected]
  | +-- [email protected] deduped
  | +-- [email protected] deduped
  | +-- [email protected] deduped
  | +-- [email protected]
  | | `-- [email protected] deduped
  | `-- [email protected]
  |   `-- [email protected]
  +-- @google-cloud/[email protected]
  +-- @google-cloud/[email protected]
  +-- [email protected]
  +-- [email protected]
  +-- [email protected]
  +-- [email protected]
  | +-- [email protected]
  | | -- [email protected]
  | |   -- [email protected]
  | +-- [email protected]
  | +-- [email protected]
  | | +-- [email protected] deduped
  | | +-- [email protected]
  | | | -- [email protected] deduped
  | | -- [email protected]
  | -- [email protected]
  +-- [email protected]
  +-- [email protected]
  | +-- [email protected]
  | +-- [email protected]
  | +-- [email protected]
  | | +-- [email protected]
  | | | `-- [email protected]
  | | +-- [email protected] deduped
  | | +-- [email protected] deduped
  | | `-- [email protected]
  | +-- [email protected]
  | | +-- [email protected] deduped
  | | `-- [email protected]
  | |   `-- [email protected]
  | +-- [email protected]
  | | +-- [email protected] deduped
  | | +-- [email protected]
  | | | +-- [email protected]
  | | | `-- [email protected] deduped
  | | +-- [email protected] deduped
  | | +-- [email protected]
  | | `-- [email protected]
  | +-- [email protected]
  | | +-- [email protected]
  | | | `-- [email protected]
  | | |   `-- [email protected]
  | | `-- [email protected]
  | |   `-- [email protected]
  | +-- [email protected]
  | | +-- [email protected]
  | | | +-- [email protected]
  | | | +-- [email protected]
  | | | | `-- [email protected] deduped
  | | | `-- [email protected] deduped
  | | `-- [email protected]
  | +-- [email protected]
  | | `-- [email protected]
  | `-- [email protected]
  +-- [email protected]
  | +-- @grpc/[email protected]
  | | `-- [email protected] deduped
  | +-- @grpc/[email protected]
  | | +-- [email protected]
  | | `-- [email protected] deduped
  | +-- [email protected] extraneous
  | +-- [email protected] deduped
  | +-- [email protected]
  | | +-- [email protected] deduped
  | | `-- [email protected] extraneous
  | +-- [email protected]
  | | +-- [email protected] deduped
  | | +-- [email protected]
  | | +-- [email protected]
  | | +-- [email protected] extraneous
  | | `-- [email protected] extraneous
  | +-- [email protected]
  | | +-- [email protected] deduped
  | | `-- [email protected] deduped
  | +-- [email protected] deduped
  | +-- [email protected]
  | +-- [email protected]
  | +-- [email protected] deduped
  | +-- [email protected]
  | | `-- [email protected] extraneous
  | +-- [email protected] deduped
  | `-- [email protected]
  +-- [email protected]
  +-- [email protected]
  +-- [email protected]
  +-- [email protected]
  +-- [email protected]
  +-- [email protected]
  +-- [email protected]
  | +-- @protobufjs/[email protected]
  | +-- @protobufjs/[email protected]
  | +-- @protobufjs/[email protected]
  | +-- @protobufjs/[email protected]
  | +-- @protobufjs/[email protected]
  | | +-- @protobufjs/[email protected] deduped
  | | `-- @protobufjs/[email protected] deduped
  | +-- @protobufjs/[email protected]
  | +-- @protobufjs/[email protected]
  | +-- @protobufjs/[email protected]
  | +-- @protobufjs/[email protected]
  | +-- @protobufjs/[email protected]
  | +-- @types/[email protected]
  | +-- @types/[email protected]
  | `-- [email protected]
  `-- [email protected]
    +-- [email protected] deduped
    `-- [email protected]

npm ERR! extraneous: [email protected] H:\ReteAI\tmp\node_modules\google-gax\node_modules\duplexify
npm ERR! extraneous: [email protected] H:\ReteAI\tmp\node_modules\google-proto-files\node_modules\walkdir
npm ERR! extraneous: [email protected] H:\ReteAI\tmp\node_modules\grpc\node_modules\node-pre-gyp
npm ERR! extraneous: [email protected] H:\ReteAI\tmp\node_modules\grpc\node_modules\protobufjs
npm ERR! extraneous: [email protected] H:\ReteAI\tmp\node_modules\retry-request\node_modules\through2

callmehiphop · 2019-02-27T14:28:11Z

@nirbenda Our dependency list looks the same, although I'm not getting any extraneous errors. Are you running npm dedupe or using any additional Google Cloud Node.js clients in the same project?

nirbenda · 2019-02-27T20:35:53Z

I got this problem on another project I have, but I had created this totally separated project that includes only the code I presented above.

ajaaym · 2019-02-27T20:48:47Z

@nirbenda this might not make any difference, but can you try loading const {PubSub} = require('@google-cloud/pubsub'); outside function?

var http = require('http');
 const {PubSub} = require('@google-cloud/pubsub');
async function listenForErrors(subscriptionName) {

callmehiphop · 2019-02-27T21:10:24Z

@nirbenda Could you share your package-lock.json file?

nirbenda · 2019-02-27T21:22:32Z

@ajaaym , tried to do what you offered, same results :(.
@callmehiphop , here is my package-lock.json (renamed to .txt)

package-lock.txt

callmehiphop · 2019-02-28T12:29:41Z

Unfortunately I'm still unable to reproduce :( would you mind testing with older versions of the client? If we can find the last version that does not produce this error it might help us to determine what changes could be causing it.

nirbenda · 2019-02-28T13:07:22Z

@callmehiphop Sure, which version do you suggest to start from?

callmehiphop · 2019-02-28T13:17:30Z

Lets try with the following

0.24.1
0.23.0
0.22.2

nirbenda · 2019-02-28T21:14:41Z

@callmehiphop In version 0.24.1 I could not reproduce this issue. I will let it work for a couple of hours just to be sure.
Which version do you think it is best to check next?

callmehiphop · 2019-02-28T21:18:18Z

@nirbenda I don't think there's any need to check other versions, I'm going to go through the commits between 0.24.1 and 0.25.0 and see if there's anything obvious that might be causing the issue. Thanks for testing it out!

nirbenda · 2019-03-01T01:58:51Z

@callmehiphop unfortunately, it took longer but it happened also in 0.24.1 as well.
I will check the other versions now.

nirbenda · 2019-03-01T06:31:53Z

@callmehiphop In version 0.23.0 it doesn't seem to reproduce, I am having another issue after running for a while (ERROR: error: 14 UNAVAILABLE: TCP Read failed) but I think this might be already fixed in newer versions.
I tracked the memory usage and it seems to be stable (below 40MB).
So I think it might be something between 0.23.0 and 0.24.1.
Thanks :)

callmehiphop · 2019-03-04T21:30:49Z

@nirbenda thanks for the report! It looks like between 0.23.0 and 0.24.1 we upgraded 2 of our core dependencies. I suspect the issue is coming from one of them, but I'm probably going to need your help determining which one since I've been largely unsuccessful at reproducing your issue so far 😢

The dependencies in question are:

It looks like neither one required a code change, so we should be able to just rollback the version in order to test.

nirbenda · 2019-03-06T07:43:03Z

I tried reverting those two libraries to previous versions, but the memory leak still occurred after a while.
Now I have reverted again to 0.23.0 just to be sure that it does not happen.
Any other idea?

nirbenda · 2019-03-06T08:52:50Z

@callmehiphop By the way, on the 0.23.0 version I get this error EXACTLY after 900 messages (checked twice), therefore it is problematic to check a long-running process. Although monitoring the memory in the 0.23.0 version seems to show now indication of a memory leak.
Any other ideas?


Message: [object Object] 895
Message: [object Object] 896
Message: [object Object] 897
Message: [object Object] 898
Message: [object Object] 899
Message: [object Object] 900
ERROR: Error: 14 UNAVAILABLE: TCP Read failed
ERROR: Error: 14 UNAVAILABLE: TCP Read failed
ERROR: Error: 14 UNAVAILABLE: TCP Read failed
ERROR: Error: 14 UNAVAILABLE: TCP Read failed
ERROR: Error: 14 UNAVAILABLE: TCP Read failed

callmehiphop · 2019-03-06T18:52:20Z

I'm at a bit of a loss really, being unable to reproduce makes it almost impossible to determine the root issue. If I had to speculate I would think the memory leak would come from 1 of 2 places

Subscription flow control bug
Native grpc error

Which would lead me to guess that this might be a grpc error since we've kind of ruled out the possibility of a flow control bug. @nirbenda if you want to try and profile the memory leak and give us back results that might help? Otherwise maybe we should try and pull in another pair of eyes. @stephenplusplus do you have any bandwidth to try and reproduce this?

callmehiphop · 2019-03-18T19:41:04Z

@JustinBeckwith is there anyone else we could try and pull in on this to attempt a repro?

callmehiphop · 2019-04-22T19:22:48Z

Hasn't been any activity here in quite some time, I'm going to close this for now. If any new info becomes available I'll be more than happy to re-open and investigate again.

* build: switch to GitHub magic proxy * lint: fix linting

callmehiphop added status: investigating The issue is under investigation, which is determined to be non-trivial. needs more info This issue needs more information from the customer to proceed. labels Feb 27, 2019

nirbenda closed this as completed Feb 27, 2019

nirbenda reopened this Feb 27, 2019

callmehiphop added the help wanted We'd love to have community involvement on this issue. label Mar 25, 2019

callmehiphop changed the title ~~Memory Leak on Subscription~~ Memory Leak on Subscription (Windows) Mar 25, 2019

callmehiphop removed the status: investigating The issue is under investigation, which is determined to be non-trivial. label Mar 25, 2019

yoshi-automation added triage me I really want to be triaged. 🚨 This issue needs some love. labels Mar 25, 2019

callmehiphop added priority: p2 Moderately-important priority. Fix may not be included in next release. and removed 🚨 This issue needs some love. triage me I really want to be triaged. labels Mar 26, 2019

sduskis added the type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns. label Apr 18, 2019

callmehiphop closed this as completed Apr 22, 2019

google-cloud-label-sync bot added the api: pubsub Issues related to the googleapis/nodejs-pubsub API. label Jan 31, 2020

yoshi-automation added the 🚨 This issue needs some love. label Apr 6, 2020

JustinBeckwith assigned nirbenda Feb 1, 2021

feywind pushed a commit to feywind/nodejs-pubsub that referenced this issue Nov 12, 2024

feat: support apiEndpoint override (googleapis#500)

89124f6

* build: switch to GitHub magic proxy * lint: fix linting

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Memory Leak on Subscription (Windows) #500

Memory Leak on Subscription (Windows) #500

nirbenda commented Feb 27, 2019 •

edited

Loading

callmehiphop commented Feb 27, 2019

nirbenda commented Feb 27, 2019

callmehiphop commented Feb 27, 2019

nirbenda commented Feb 27, 2019

callmehiphop commented Feb 27, 2019 •

edited

Loading

nirbenda commented Feb 27, 2019 •

edited

Loading

callmehiphop commented Feb 27, 2019

nirbenda commented Feb 27, 2019

ajaaym commented Feb 27, 2019

callmehiphop commented Feb 27, 2019

nirbenda commented Feb 27, 2019

callmehiphop commented Feb 28, 2019

nirbenda commented Feb 28, 2019

callmehiphop commented Feb 28, 2019

nirbenda commented Feb 28, 2019

callmehiphop commented Feb 28, 2019

nirbenda commented Mar 1, 2019

nirbenda commented Mar 1, 2019

callmehiphop commented Mar 4, 2019

nirbenda commented Mar 6, 2019

nirbenda commented Mar 6, 2019

callmehiphop commented Mar 6, 2019 •

edited

Loading

callmehiphop commented Mar 18, 2019

callmehiphop commented Apr 22, 2019

Memory Leak on Subscription (Windows) #500

Memory Leak on Subscription (Windows) #500

Comments

nirbenda commented Feb 27, 2019 • edited Loading

Environment details

Steps to reproduce

callmehiphop commented Feb 27, 2019

nirbenda commented Feb 27, 2019

callmehiphop commented Feb 27, 2019

nirbenda commented Feb 27, 2019

callmehiphop commented Feb 27, 2019 • edited Loading

nirbenda commented Feb 27, 2019 • edited Loading

callmehiphop commented Feb 27, 2019

nirbenda commented Feb 27, 2019

ajaaym commented Feb 27, 2019

callmehiphop commented Feb 27, 2019

nirbenda commented Feb 27, 2019

callmehiphop commented Feb 28, 2019

nirbenda commented Feb 28, 2019

callmehiphop commented Feb 28, 2019

nirbenda commented Feb 28, 2019

callmehiphop commented Feb 28, 2019

nirbenda commented Mar 1, 2019

nirbenda commented Mar 1, 2019

callmehiphop commented Mar 4, 2019

nirbenda commented Mar 6, 2019

nirbenda commented Mar 6, 2019

callmehiphop commented Mar 6, 2019 • edited Loading

callmehiphop commented Mar 18, 2019

callmehiphop commented Apr 22, 2019

nirbenda commented Feb 27, 2019 •

edited

Loading

callmehiphop commented Feb 27, 2019 •

edited

Loading

nirbenda commented Feb 27, 2019 •

edited

Loading

callmehiphop commented Mar 6, 2019 •

edited

Loading