Memory leak when using with Solid Cable

[fdaugs]

Summary

If you use lograge-sql together with solid cable there is a memory leak, because the queries that solid cable makes are stored by lograge-sql, but never logged and thus retained in memory. Since solid will be the default action cable adapter from Rails 8 onwards, I think it would be best to filter these queries by default.

Details

After deploying solid cable wie noticed a constant memory increase:

.

Inspection of the heap showed that a significant amount of memory was being used by this gem:

> heapy diff heap-1.json heap-2.json heap-3.json | grep Retained | head -4
Retained STRING 140849 objects of size 45071432/52941087 (in bytes) at: /usr/local/bundle/gems/lograge-sql-2.4.0/lib/lograge/sql.rb:54
Retained STRING 17676 objects of size 913880/52941087 (in bytes) at: /usr/local/bundle/gems/activerecord-7.1.4.2/lib/active_record/connection_adapters/postgresql/oid/type_map_initializer.rb:20
Retained DATA 7631 objects of size 610480/52941087 (in bytes) at: /usr/local/bundle/gems/activerecord-7.1.4.2/lib/active_record/connection_adapters/postgresql/oid/type_map_initializer.rb:96
Retained IMEMO 7343 objects of size 616616/52941087 (in bytes) at: /usr/local/bundle/gems/activerecord-7.1.4.2/lib/active_record/connection_adapters/postgresql/oid/type_map_initializer.rb:96

The retained strings in the heap snapshot are actually all polling queries by solid cable. I think what happens is, that these queries are stored here, but never get cleared because they are outside of a request context.

Possible solutions

1. Since solid cable will be the default action cable adapter and these queries don't add much value anyway, I think it would be best to skip storing these queries by default. I'm not sure if a configuration option to disable this behavior is even necessary.
2. Another solution would be to allow passing a lambda function, to determine whether a query should be stored, but then everyone would have to discover this leak for themselves.

I'm happy to open a PR once we've agreed on how to proceed!

[iMacTia]

Hi @fdaugs and thank you for spotting and reporting this!
I don't personally use ActionCable in my project, but based on your explanation above I completely agree this should be something we avoid so that people don't have to experience and investigate the memory leak before finding out.

For that reason, I'm all for skipping SolidCable queries by default rather than making this configurable 👍

I only have one question though: I believe ActionCable runs as a separate process and therefore does not use lograge (since it doesn't go through the normal request/response cycle and possibly middleware stack). Does it even make sense to have lograge-sql setup in that case? Could we have a similar issue with other processes that share the Rails application initialisation (e.g. Sidekiq)? Maybe an even better solution would be to short-circuit log rage/sql/extension so that it doesn't prepend the module unless the Rails server is running and/or lograge is configured?

[fdaugs]

Hi @iMacTia,

thanks for your response!
actually it seems to be running in a different thread according to the documentation and the implementation of solid cable. I think the simplest solution do just add a addition condition to the valid? function:

def valid?(event)
      return false if event.payload[:name] == 'SCHEMA' || event.payload[:name].include?('SolidCable::')
      
      # Only store SQL events if `event.duration` is greater than the configured +min_duration+
      # No need to check if +min_duration+ is present before as it defaults to 0
      return false if event.duration.to_f.round(2) < Lograge::Sql.min_duration_ms.to_f

      true
end

But this will lead to a tight coupling to the solid_cable gem. Maybe it would be better to make this an configurable option as array or even a lambda with "SolidCable::" included in the default options like so:

def valid?(event)
      return false if event.payload[:name] === Regexp.union(Rails.application.config.lograge_sql.invalid_query_names) # Default would be ['SCHEMA', 'SolidCable::']
      
      # Only store SQL events if `event.duration` is greater than the configured +min_duration+
      # No need to check if +min_duration+ is present before as it defaults to 0
      return false if event.duration.to_f.round(2) < Lograge::Sql.min_duration_ms.to_f

      true
end

This on the other hand is not really transparent and potentially confusing, because in surfaces internal implementation details and there already is an option named query_filter wich does something different.

[iMacTia]

Well, I just found out that Lograge officially added support for ActionCable, so I guess my suggestion to just disable lograge-sql there doesn't make much sense anymore 😄
I'm a bit surprised though as to why SQL logs are never cleared though, can I ask which version of lograge do you use?

I'd be inclined to go with your suggestion and add a configurable denylist for payload names.
The Regexp.union solution shown above is a bit simplistic though. In the case of SCHEMA we'd want an exact match, while for SolidCable:: we'd want the name to start with that. Maybe it makes more sense for this name_denylist to just be an array of Regexp so that we have more control over each.

Then in valid? we loop through the array and check of the even name matches. If it does, we discard the event.

[fdaugs]

We're using lograge version 0.14.0. Which is the current version.

I'm a bit confused about your first sentence :D Just to clear things up:

• Rails 8 added Solid Cable by default.
• Solid Cable is an Action Cable adapter. (How the broadcasted messages are distributed between instances of the same application, because clients connect to different instances via websocket, but need to get the same messages). There are more options than solid cable but this is the only one that causes this particular problem because it uses a database-backed polling approach.
• And Action Cable is the websocket-specific part of the Rails framework. It's an abstraction layer over the various adapters.

I think in terms of a solution we were pretty close. I will open a PR and implement the array of regexp. We can discuss the details there.

[iMacTia]

Ah I guess this is where I was getting confused:

solid cable uses a database-backed polling approach

What I originally understood was that solid cable queries where being stored in the thread-memory cache and never dumped, but that was surprising since Lograge supports ActionCable, meaning after a successful websocket message it should log and therefore empty the thread-memory cache.

However based on your latest message I now suspect that works correctly, but the issue is that the constant polling causes queries to be stored and if you don't have a websocket request for a while these are never cleared?

Anyway, happy to proceed as we discussed above, this was just my desire to get a better understanding of the problem 🙂

[fdaugs]

However based on your latest message I now suspect that works correctly, but the issue is that the constant polling causes queries to be stored and if you don't have a websocket request for a while these are never cleared?

I'm also not 100% sure what happens here but I think that queries of solid cable even originate outside of the context of the methods lograge subscribes to.

As of my understanding solid cable works like this:

If you broadcast a message then lograge will log these (because perform_action is called. Then the message is written into a solid_cable_messages table in the databases. THEN there is a separate thread running in every rails server instance that was created by solid cable. This thread polls the table and sends the messages to the clients. And because this has not much to do with action cable its not catched by lograge.

[iMacTia]

Fixed in #60 🎉
Thank you again for your work @fdaugs 🙇