Rails 5: empty begin commit for no reason

[PeterMozesMerl]

I’ve upgraded from Rails 4.2.10 to 5.2.1. I noticed in the log that every request ended with

   (0.2ms)  BEGIN
   (0.1ms)  COMMIT

They look different than the rest of the query logs as they come after a few empty lines, after each request.

Neither the native config.active_record.verbose_query_logs = true nor the active_record_query_trace exposed where these two lines came from. Also, turning off the query log/gem did not help me remove it.

I’ve created a new Rails application with PostgreSQL adapter. As soon as the active_record_query_trace gem is in the Gemfile and it’s initialized, it add an empty transaction after each request. This is true when there is neither any other database activity nor the session was touched in any way in the local code.

It doesn’t happen in the 4.2.10 version of my application even though that has a dozen gems and callbacks everywhere (including active_record_query_trace of course). But it happens in an otherwise empty 5.2.1 Rails application after each request.

The issue is not how much time it takes on a local server. (Although, it has slowed down my landing page by 25%).

The significant problem arises when one wants to have application servers in multiple data centers using a single master database setup. (That’s what you can have in the NO-NOSQL world).

Reaching the remote master database node takes much time, especially when it’s on another continent. It should happen only on write. Right now, I don’t even now how to control where this query is sent. It shouldn’t be sent anywhere in the first place, when it’s empty, as it was not with Rails 4.2.10.

[sikachu]

Thank you for the report. Apparently, this is a known Rails issue, and the core team just recently merged a patch into master: rails/rails#32647

That patch will come out when Rails 6.0 ships, so it might be a while until then.

[PeterMozesMerl]

Are you sure it’s the same issue?

Rails 4.2.10 sends the empty begin end block in various cases.

$ rails console
Loading development environment (Rails 4.2.10)
2.5.1 :001 > RandomModel.first.save
  Session Load (0.7ms)  SELECT  "xxx".* FROM "xxx"  ORDER BY "xxx"."id" ASC LIMIT 1
   (0.1ms)  BEGIN
   (0.2ms)  COMMIT
 => true
2.5.1 :002 > RandomModel.transaction { }
   (0.1ms)  BEGIN
   (0.1ms)  COMMIT
 => nil
2.5.1 :003 > RandomModel.connection.transaction { }
   (0.2ms)  BEGIN
   (0.2ms)  COMMIT
 => nil

Just like in 5.2.1. The referenced Rails issue (rails/rails#17937) says that Rails 2 and 3 behaved the same way.

However, activerecord-session_store does not generate the empty begin end blocks with Rails 4.2.10. The gem version is the same.

$ bundle | egrep 'Using (rails |activerecord-session_store)'
Using activerecord-session_store 1.1.1
Using rails 4.2.10

$ bundle | egrep 'Using (rails |activerecord-session_store)'
Using activerecord-session_store 1.1.1
Using rails 5.2.1

Only the latter one sends the empty blocks, and only with an initialized activerecord-session_store.

[sikachu]

If the gem version are the same, it seems like the problem lies in Rails itself.

One assumption on why this start to happen on 5.2.1. might be because it starts to call save_session even when you haven't touched the session at all. Calling save_session will trigger save even there's no change to the session.

[PeterMozesMerl]

Thank you. I believe you are right about the reason. Then the fix of rails/rails#17937 should fix it as well.

In case my new database setup will be ready sooner than Rails 6, I will look deeper into this.

Thank you for the answer and for working on this gem.