Possible Memory Leak with gRPC

[adamunchained]

Hi Guys,

I hope someone will be able to help me with this one. I spend over few days on this and I can't figure out the issue. We used RabbitMQ as our messaging queue system but now switched over to Google Pub/Sub. All the other code stayed same. We suddenly experiencing memory leak so I naturally assumed it's an issue with gcloud-node lib. See graph below:

I fully reviewed our implementation of the "gcloud-node" twice and it's following all the standard guidelines. I went down the debugging path and it seems "Rc" object is continuously growing. See attached screenshot where I'm compering Heaps snapshots 48 minutes apart:

Few notes:

• we're using pull method
• please note I'm not expert on investigating memory leaks in NodeJS. I think I'm more guessing ATM.
• we only experiencing this issue on our publisher that runs 24/7. It publishes on average around 10 events per second (very low traffic atm). It seems memory usage increases much faster. It runs on GCP.
• As you can see publisher goes above 1Gb of memory after 9h
• Server runs on NODE.js 4.2.1 (being moved to 4.4.5). I tested locally on 4.4.4. I don't think it's version related tbh.
• it seems the issue is not related to "quantity" of events pushed but it's more related to the process running time

[stephenplusplus]

Thanks for reporting! We had a report a while back suspecting gRPC of a leak as well (#1164). We made some corrections in how we were caching connections. (If you're interested, here's a nice explanation of the lifecycle of a gRPC call: #1164 (comment))

I opened an issue on gRPC about it (grpc/grpc#5970), but the maintainer wasn't able to reproduce, so we called it case closed.

Is it possible to get some sample code together to reproduce? And just to make sure, are you using a version of gcloud-node >= 0.30.0?

[adamunchained]

yep, I'm using version 0.34.0.

I'm having hard time to replicate the memory leak by performing immediate operations as it seems to increase over time instead. I'll try to put something together today and come back to you.

[dennismartensson]

Hi @adamkundrat and @stephenplusplus I have also seen this problem running nodejs 4.2.4 LTS and gcloud ^0.32.0 when running a lot of topic.publish

Please let me know how I can help!

[stephenplusplus]

I put together a repo that might be a framework which we can test this: https://github.com/stephenplusplus/gissue-1356 -- feel free to modify anything to get it to reproduce, even if it takes leaving it running for 9 hours. 🕘

[adamunchained]

sorry @stephenplusplus I didn't see your post early enough and went straight into coding. I just put this attached example together trying to replicate similar way we are using it. You can see over time the memory usage is growing. I did this in last hour I hope I didn't introduce another memory leak...

I tried not to use any external libraries to isolate this. I hope async (eachLimit) is not responsible for any memory usage. I'll work to remove the "async" just to make sure but I hope it's a good start.

https://gist.github.com/adamkundrat/6c994b9086404e807592e2e679ae1428

BTW - I've slower connection where are I'm so it does not publish large number of items. Although if you're on the fast network it could be a different story:)

[adamunchained]

Here is a gist without using async - eachLimit: https://gist.github.com/adamkundrat/1dc2631e260a2f380d187fb9a0ce1825

I ran it for few minutes and you can see memory usage is growing:
Date: Fri Jun 03 2016 10:57:46 GMT+1000 (AEST), Memory: 37.52Mb
Date: Fri Jun 03 2016 10:58:46 GMT+1000 (AEST), Memory: 83.75Mb
Date: Fri Jun 03 2016 11:00:46 GMT+1000 (AEST), Memory: 140.9Mb
Date: Fri Jun 03 2016 11:01:16 GMT+1000 (AEST), Memory: 168.25Mb
Date: Fri Jun 03 2016 11:04:16 GMT+1000 (AEST), Memory: 289.26Mb
Date: Fri Jun 03 2016 11:05:16 GMT+1000 (AEST), Memory: 258.29Mb
Date: Fri Jun 03 2016 11:06:46 GMT+1000 (AEST), Memory: 419.73Mb
Date: Fri Jun 03 2016 11:07:16 GMT+1000 (AEST), Memory: 337.64Mb
Date: Fri Jun 03 2016 11:07:46 GMT+1000 (AEST), Memory: 382.72Mb

Based on the monitoring I'm submitting around 8 items per second per queue (script is creating 40 queues).

Thank you for any help guys. Highly appreciated.

[stephenplusplus]

I've adapted your test to one that can switch between using gRPC-only and gcloud-node: https://github.com/stephenplusplus/gissue-1356/blob/master/test-2.js

I noticed you're bypassing errors that publish() receives, including many 429s (too many requests, QPS limit reached). Even though you aren't slowing for those, gcloud-node uses an exponential backoff retry strategy, which will make the same failed request 2 more times.

To fairly compare between gRPC and gcloud-node isn't easily done right now, because of some bugs I caught while investigating (#1357). It requires going into the gcloud-node code...

# node_modules/gcloud-node/lib/common/grpc-service.js#260
- maxRetries: this.maxRetries
+ retries: this.maxRetries

However, once you do that, the memory usage is pretty similar between both. Here's the output when using gcloud-node:

$ export USE_GCLOUD=1 && node ./test-2.js
Using gcloud-node...
Date: Fri Jun 03 2016 14:41:13 GMT-0400 (EDT), Memory: 47.36Mb
gRPC service created
Topics found or created
Date: Fri Jun 03 2016 14:41:23 GMT-0400 (EDT), Memory: 299.19Mb
Date: Fri Jun 03 2016 14:41:33 GMT-0400 (EDT), Memory: 311.04Mb
Date: Fri Jun 03 2016 14:41:43 GMT-0400 (EDT), Memory: 318.4Mb
Messages published
Date: Fri Jun 03 2016 14:41:51 GMT-0400 (EDT), Memory: 318.5Mb
Done!
Date: Fri Jun 03 2016 14:41:53 GMT-0400 (EDT), Memory: 318.51Mb

gRPC alone looked like this:

$ export USE_GCLOUD= && node ./test-2.js
Date: Fri Jun 03 2016 14:42:15 GMT-0400 (EDT), Memory: 52.92Mb
gRPC service created
Topics found or created
Date: Fri Jun 03 2016 14:42:25 GMT-0400 (EDT), Memory: 242.35Mb
Date: Fri Jun 03 2016 14:42:35 GMT-0400 (EDT), Memory: 253.85Mb
Date: Fri Jun 03 2016 14:42:45 GMT-0400 (EDT), Memory: 261.26Mb
Messages published
Date: Fri Jun 03 2016 14:42:51 GMT-0400 (EDT), Memory: 277.63Mb
Done!
Date: Fri Jun 03 2016 14:42:55 GMT-0400 (EDT), Memory: 277.64Mb

So, if you need to just have a constant throughput, without handling the QPS limit being reached, you would want to set the maxRetries to 0 (once we support that... thanks to you for this issue allowing us to catch it!).

If possible within the requirements of your application, a better solution might involve throttling the rate of publishing. You can limit the QPS by batching multiple messages together per publish call. Also, be sure to check the Quota page to make sure you are using the max available to you. My numbers: 17,000 - 1,000 - 10,000,000 - 20,000,000. If these are still too low, you can apply for a higher quota from that page as well.

@adamkundrat and @dennismartensson: does this research sound relevant to your experiences, or did I miss any nuances?

I'll let you know as soon as we release the fix for maxRetries.

// cc @tmatsuo since we're talking Pub/Sub.

[dennismartensson]

Hi,

I think that could make sense. I have just made some changes and are deploying them to some of our servers so we can see if those machines gets the same problem when only postings ones a second on two topics. Instead of around 10 times per second per topic.

[adamunchained]

Thanks @stephenplusplus
Will test it on our servers and let you know the result.

[stephenplusplus]

@adamkundrat did you see any improvements?

[adamunchained]

sry for the delayed response. I was away for the best part of the week. Your suggestion actually helps and the memory consumption is much better now. Thanks heaps!

[stephenplusplus]

No problem, and that's great!