Repository navigation
grpc-js 1.4.1 - Channelz tracing uses unbounded memory which causes OOM #1941
Description
Problem description
Up front: I wouldn't necessarily call this a bug but it has caused an issue in our code.
We use a single grpc-js client to service calls to the Google Ads API. This is instantiated when the server is initialized and used throughout the life of the program to try and reduce memory leakage. This works quite well, memory use is relatively stable, but when grpc-js is upgraded to 1.4.1 (from 1.3.7), memory usage starts to increase linearly even though our implementation is the same. This seems to be caused by Date objects (and others) being created when events are appended to the ChannelzTrace object associated with our channel.
This may otherwise be a small amount of memory but we service a very large amount of traffic through this server and it eventually causes an OOM event.
Should we cease caching our grpc client? What would be the recommended lifecycle of a client in that case? Or is there a way to opt out of tracing?
Reproduction steps
Create a single grpc Client object and fire traffic to it at a rate of 5 requests per second over 10 minutes and observe memory usage climbing without reaching a cap.
Environment
- OS name, version and architecture - Tested on Linux ARM64 and macOS ARM64
- Node version - 16
- Node installation method - Docker image on server and nvm locally
- Package name and version - 1.4.1
Additional context
I'm not sure what would be most helpful but I am happy to provide anything required.
Activity
[-]1.4.1 - Channelz tracing uses unbounded memory which causes OOM[/-][+]grpc-js 1.4.1 - Channelz tracing uses unbounded memory which causes OOM[/+]murgatroid99 commentedon Oct 18, 2021
It's not supposed to do traces on a per-request basis. The traces are all about connection state, which shouldn't change more quickly when there are more requests. Because of that, if anything, caching the client should decrease the number of traces that occur, so I wouldn't recommend changing that.
It might help to see what information is actually getting stored in channelz in your case. You can run a channelz server with code like this:
Then you can access it using the
grpcdebugtool. I would be interested to see the output ofgrpcdebug <server address> channelz channelsandgrpcdebug <server address> channelz channel <channel id>where "server address" is the address of the channelz server, and "channel id" is the ID of one of the channels from the first command that has a significant number of calls started.In the meantime, I will push out an update that rotates out old channelz trace events on a per-channel/subchannel/server basis.
tom-engineering commentedon Oct 19, 2021
Thank you for the swift and helpful response! We have had issues with pushing too many concurrent requests down the same channel which seems to (at least implicitly) affect channel status, and we force round-robin on as well - I don't suppose that may be adding to the volume of trace events? I will find some time to inspect the channelz logs.
murgatroid99 commentedon Oct 19, 2021
I would be interested to see a trace log for one of your tests, which can be output by setting the environment variables
GRPC_TRACE=allandGRPC_VERBOSITY=DEBUG. They should show the details of the things you are describing.murgatroid99 commentedon Oct 26, 2021
This took a little longer than I expected, but grpc-js version 1.4.2 is out with two relevant changes: Each channel, subchannel, and server will now store only a limited number of trace events at any one time, and channelz stats tracking can be disabled entirely for a channel and its subchannels, or a server, with the channel option
'grpc.enable_channelz': 0.murgatroid99 commentedon Nov 1, 2021
If that change does solve the problem, it would still help to see a log to understand what caused the problem in the first place.
tom-engineering commentedon Nov 5, 2021
Posting this here as a potential FYI as it may be a bug with Google Ads API (or us messing something up) but setting the
'grpc.enable_channelz': 0option using grpc-js 1.4.2 makes all our calls to the Google Ads API exceed deadline (set to 60s). I've tried to condense down the code we actually use to make the request but I've had to cut quite a bit, hopefully it may provide some clues. I'll post any updates if we find them.Not setting the
"grpc.enable_channelz"option at all works seemingly fine, and setting a random unknown option of"grpc.unknown_option": 0works fine as well (was testing to see if it passes the value to the GA API which potentially doesn't like it).murgatroid99 commentedon Nov 5, 2021
No, now that you pointed it out, I found a bug with the handling of that option in grpc-js. I will fix that. In the meantime, without that option, do you still see the unbounded memory growth?
tom-engineering commentedon Nov 5, 2021
We are still seeing significant additional memory usage over the baseline (so far about 2.5x memory usage - 800MiB to 2GiB), but we do now utilise a static pool of grpc clients so there may be many multiples of channels and subchannels logging. I'm just waiting to see if it tops out or keeps going in prod but we may hit our memory limit still so bear with me on that. I'll try and get a sample of some logs in the meantime.
murgatroid99 commentedon Nov 5, 2021
The bug with that option is fixed in version 1.4.3.
Gilwe commentedon Nov 7, 2021
Hi, we're in the same boat but we see also an increase in memory with 1.4.3 (also node 16).
Our case is an express server that serves graphql and for each graphql will call an internal grpc service. when we used
grpclibrary we had no memory problems but with@grpc/grpc-nodethe memory is climbing on every request.When I took a heap snapshot I noticed that we had a lot of
ChannelImplementationrows so I explicitly ranclosefor all the grpc clients (client = all services created fromgrpc.loadPackageDefinition()) which made the memory increment not to be as steep but the memory leak was still there.I tried to specify
enable_channelz:0but saw no improvement.@murgatroid99 logs from what would be helpful for you?
tom-engineering commentedon Nov 8, 2021
@murgatroid99 I am casting around in the dark so I really apologise if this is way off and a distraction but is this line the culprit?
grpc-node/packages/grpc-js/src/subchannel.ts
Line 558 in cb29b6a
There's a guarded invocation in the same function that assigns the output to a ref, but then this unguarded invocation that does nothing with the output at the end of the function. I'm wondering if the unguarded version should be there at all?
I don't seem to get a memory leak if I comment out the unguarded line when
enable_channelz:0is set, so it's possible that this may be the cause of the actual leak and why turningenable_channelzoff doesn't seem to help.murgatroid99 commentedon Nov 8, 2021
You're right, that line shouldn't be there at all, which explains why I missed it when adding the guards, and the output never gets recorded, so it never gets unregistered. I have published a new version 1.4.4 that removes it.
@Gilwe A lot of
ChannelImplementationobjects is a big red flag here. If you are creating a new client object for every request you make, that would leak a lot of memory. We discourage that usage pattern, instead you should create one client, and use it to make all of your requests. If you do have to create many clients, you shouldcloseeach one when you are done using it.Even with the extra line mentioned in the last comment, setting the channel option to disable channelz should have had a significant impact on the rate of the memory leak, if you set the option
'grpc.enable_channelz': 0as stated in my earlier comment. If you actually tried to set an option calledenable_channelz, that would do nothing because it's not a recognized option.If you still have problems with the new version, as stated in my earlier comment, the logs that would help here are client trace logs, which you can get by running your code with the environment variables
GRPC_TRACE=allandGRPC_VERBOSITY=DEBUG. Just the first few hundred lines would probably be enough to understand what is happening.tom-engineering commentedon Nov 8, 2021
1.4.4 has completely fixed the memory leak for me with channelz tracing disabled, thank you! Not sure if the above was to me or @Gilwe but I had been setting
"grpc.enable_channelz"correctly, I had just abbreviated in my comment.In terms of the actual channelz tracing itself, in our case it looks like it might be frequent TRANSIENT_FAILURE state transitions that fill up the logs. This is a set of entries from a completely idle application I left running by accident on my local machine just now with no traffic going through it:
Is that expected behaviour?
From my side, given that we no longer experience a memory leak and we have the option of disabling channelz tracing, I consider my issue completely resolved - but I'm more than happy to continue to contribute logs or testing if there is more that can be done. Thank you again for your help @murgatroid99
murgatroid99 commentedon Nov 8, 2021
It looks like the server is telling the client to go away after the connection is idle for 75 seconds. The client behavior when handling that is normal, specifically for the
round_robinload balancing policy.round_robintries to keep all of its connections alive, so it will reconnect every time the server tells it to go away. The defaultpick_first, on the other hand, will simply let the connection drop until the user makes another request.However, the total channelz memory usage should be bounded for the duration of that log. There's no mention of any channel construction, so the number of channels is constant. I see 4 instances of subchannels getting constructed, and 4 instances of them getting removed (when the refcount goes to 0), so the total number of subchannels is approximately constant. And each subchannel should register a socket with channelz when it transitions to CONNECTING, and it should unregister it when it transitions to TRANSIENT_FAILURE or IDLE, so the number of registered sockets should be constant as well. And with the changes in 1.4.3, the number of log statements retained for each is strictly limited.
Have you checked whether you still see the memory leak with channelz enabled as of 1.4.4, and if you do, can you share a log with channelz enabled of a timespan in which memory significantly increases?