Transactional Pooling on PgBouncer.

[jackcb123]

Hi again!

Would Transactional Pooling on PgBouncer mess this up w/ proxy_delay? This is what we use. We have zero writes before some reads in controllers, but we do write AFTER. I notice that many of these reads are still going to the primary unless explicitly wrapped in the connected_to :reading block.

Wouldn't it work like this with tons of concurrent requests:

Request A: performs read, then write (switching to primary, for 2 seconds)
Request B: PgBouncer may assign a connection that was previously used (in this case, by request A) that performed a write, and therefore has a last_write timestamp set, so the read goes to the primary?

[jackcb123]

I should add—when I set proxy_delay to 0 everything worked perfectly (but that seems rather unsafe given the replica isn't guaranteed to have zero lag). 0.1 delay once again did not work.

[jackcb123]

Ok, we figured it out! All is fine. Rails wraps a lot of stuff automatically in BEGIN … COMMIT, a busy app is almost always inside that 2-second window. Makara never treated BEGIN/COMMIT as writes. So that's why the difference in behavior for us when we switched to this gem instead.

WRITE_STATEMENT_MATCHERS = [
/\ABEGIN/i,
/\ACOMMIT/i,
/INSERT\s[\s\S]INTO\s[\s\S]/i,
/UPDATE\s[\s\S]*/i,
/DELETE\s[\s\S]FROM\s[\s\S]/i,
/DROP\s/i
].map(&:freeze).freeze

I removed it for us and now everything is routing properly... I wonder is there a reason to not just rely on insert, update, delete, drop solely?

[mateuscruz]

Hey @jackcb123. Sorry for the late reply, I'm only seeing this now.

You need to provide a lot more info for me to be able to help you. You should always start with at least this info (but the more you provide, the better):

• Ruby Version
• ActiveRecord / Rails version (currently, we support 4 major versions)
• ActiveRecordProxyAdapters version
• Adapter name (in this case I assume you're talking about postgresql_proxy since you mentioned PgBouncer)
• Preferrably, a dockerized sample app where the issue can be reproduced, if it's not an obvious issue

There are too many variables that could interfere with the expected behaviour and that helps narrowing down the investigation scope.

Internally, active record sends BEGIN / COMMIT statements to the database with a method that we should not be hijacking anyways (in Rails 8, it uses internal_execute which is not hijacked by the proxy) so I'm not convinced yet that that is the culprit here.

The proxy would only kick in if you had, for example, any explicit calls to a hijacked method such as to .execute('BEGIN') or .execute('COMMIT'), which is why it is part of the list of WRITE_STATEMENT_MATCHERS.

So if the behaviour you're facing is that the proxy is hijacking a regular ActiveRecord::Base.transaction {} block, that is not intended behaviour and we need a fix for it. Otherwise, I think we're in the clear.

Thanks

[mateuscruz]

@jackcb123 I just took a quick look and was able to reproduce this issue only in Rails 7.0 and I am working on a fix.

[mateuscruz]

Patches released: v0.4.7, v0.5.1 and v0.6.1.

[OskarEichler]

@mateuscruz Jumping in here on behalf of @jackcb123

We are actually on
Rails: 7.1.3.4
Ruby: 3.2.1

Does your new patch handle that version or just 7.0.X? Please check and let us know!

[mateuscruz]

Just 7.0.x. I wasn't able to reproduce this in 7.1.x

[mateuscruz]

@jackcb123 @OskarEichler this is what I used to find and fix the issue using the repo's docker compose file.

.irbrc file

# frozen_string_literal: true

load "Rakefile"
Rake::Task["environment"].invoke

require "active_record_proxy_adapters/log_subscriber"

ActiveRecord::Base.logger = Logger.new($stdout)
ActiveRecord::LogSubscriber.detach_from(:active_record)

ActiveRecordProxyAdapters.configure do |config|
  config.proxy_delay      = 2.seconds
  config.checkout_timeout = 2.seconds
end

class User < TestHelper::PostgreSQLRecord
end

After creating the databases with bundle exec appraisal ar-7.0 rake db:setup:

Then (v0.6.0)

ActiveRecord 7.0.x

/app # bundle exec appraisal ar-7.0 irb
>> BUNDLE_GEMFILE=/app/gemfiles/ar_7.0.gemfile bundle exec irb
/usr/local/lib/ruby/gems/3.4.0/gems/irb-1.14.3/exe/irb:7: warning: irb was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add irb to your Gemfile or gemspec to silence this warning.
/app/.irbrc:6: warning: benchmark was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add benchmark to your Gemfile or gemspec to silence this warning.
/usr/local/bundle/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/concern/logging.rb:1: warning: logger was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add logger to your Gemfile or gemspec to silence this warning.
Environment loaded: test
/usr/local/lib/ruby/3.4.0/irb/input-method.rb:278: warning: rdoc was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add rdoc to your Gemfile or gemspec to silence this warning.
irb(main):001> User.transaction { User.count } ; User.count 
D, [2025-07-02T16:33:59.024779 #296] DEBUG -- :   [PostgreSQLProxy Primary] TRANSACTION (0.1ms)  BEGIN
D, [2025-07-02T16:33:59.027976 #296] DEBUG -- :   [PostgreSQLProxy Primary] User Count (0.2ms)  SELECT COUNT(*) FROM "users"
D, [2025-07-02T16:33:59.029398 #296] DEBUG -- :   [PostgreSQLProxy Primary] TRANSACTION (0.2ms)  COMMIT
D, [2025-07-02T16:33:59.029792 #296] DEBUG -- :   [PostgreSQLProxy Primary] User Count (0.2ms)  SELECT COUNT(*) FROM "users"
=> 0

ActiveRecord 7.1.x

>> BUNDLE_GEMFILE=/app/gemfiles/ar_7.1.gemfile bundle exec irb
/usr/local/lib/ruby/gems/3.4.0/gems/irb-1.14.3/exe/irb:7: warning: irb was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add irb to your Gemfile or gemspec to silence this warning.
/app/.irbrc:6: warning: benchmark was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add benchmark to your Gemfile or gemspec to silence this warning.
/usr/local/bundle/gems/activesupport-7.1.3.4/lib/active_support/logger_thread_safe_level.rb:4: warning: logger was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add logger to your Gemfile or gemspec to silence this warning.
Environment loaded: test
DEPRECATION WARNING: Support for `config.active_support.cache_format_version = 6.1` has been deprecated and will be removed in Rails 7.2.

Check the Rails upgrade guide at https://guides.rubyonrails.org/upgrading_ruby_on_rails.html#new-activesupport-cache-serialization-format
for more information on how to upgrade.
 (called from Class#new at /app/lib/active_record_proxy_adapters/cache_configuration.rb:28)
/usr/local/lib/ruby/3.4.0/irb/input-method.rb:278: warning: rdoc was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add rdoc to your Gemfile or gemspec to silence this warning.
irb(main):001> User.transaction { User.count } ; User.count 
D, [2025-07-02T16:35:15.256448 #308] DEBUG -- :   [PostgreSQLProxy Primary] TRANSACTION (0.1ms)  BEGIN
D, [2025-07-02T16:35:15.260182 #308] DEBUG -- :   [PostgreSQLProxy Primary] User Count (0.2ms)  SELECT COUNT(*) FROM "users"
D, [2025-07-02T16:35:15.262102 #308] DEBUG -- :   [PostgreSQLProxy Primary] TRANSACTION (0.1ms)  COMMIT
D, [2025-07-02T16:35:15.263134 #308] DEBUG -- :   [PostgreSQL Replica] User Count (0.7ms)  SELECT COUNT(*) FROM "users"
=> 0

ActiveRecord 7.2.x

/app # bundle exec appraisal ar-7.2 irb
>> BUNDLE_GEMFILE=/app/gemfiles/ar_7.2.gemfile bundle exec irb
/usr/local/lib/ruby/gems/3.4.0/gems/irb-1.14.3/exe/irb:7: warning: irb was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add irb to your Gemfile or gemspec to silence this warning.
Environment loaded: test
/usr/local/lib/ruby/3.4.0/irb/input-method.rb:278: warning: rdoc was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add rdoc to your Gemfile or gemspec to silence this warning.
irb(main):001> User.transaction { User.count } ; User.count 
D, [2025-07-02T16:35:54.468254 #323] DEBUG -- :   [PostgreSQLProxy Primary] TRANSACTION (0.1ms)  BEGIN
D, [2025-07-02T16:35:54.472613 #323] DEBUG -- :   [PostgreSQLProxy Primary] User Count (0.3ms)  SELECT COUNT(*) FROM "users"
D, [2025-07-02T16:35:54.474591 #323] DEBUG -- :   [PostgreSQLProxy Primary] TRANSACTION (0.1ms)  COMMIT
D, [2025-07-02T16:35:54.475564 #323] DEBUG -- :   [PostgreSQL Replica] User Count (0.5ms)  SELECT COUNT(*) FROM "users"
=> 0

ActiveRecord 8.0.x

/app # bundle exec appraisal ar-8.0 irb
>> BUNDLE_GEMFILE=/app/gemfiles/ar_8.0.gemfile bundle exec irb
/usr/local/lib/ruby/gems/3.4.0/gems/irb-1.14.3/exe/irb:7: warning: irb was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add irb to your Gemfile or gemspec to silence this warning.
Environment loaded: test
/usr/local/lib/ruby/3.4.0/irb/input-method.rb:278: warning: rdoc was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add rdoc to your Gemfile or gemspec to silence this warning.
irb(main):001> User.transaction { User.count } ; User.count 
D, [2025-07-02T16:36:22.407499 #338] DEBUG -- :   [PostgreSQLProxy Primary] TRANSACTION (0.1ms)  BEGIN
D, [2025-07-02T16:36:22.407947 #338] DEBUG -- :   [PostgreSQLProxy Primary] User Count (0.5ms)  SELECT COUNT(*) FROM "users"
D, [2025-07-02T16:36:22.409437 #338] DEBUG -- :   [PostgreSQLProxy Primary] TRANSACTION (0.1ms)  COMMIT
D, [2025-07-02T16:36:22.419741 #338] DEBUG -- :   [PostgreSQL Replica] User Count (9.0ms)  SELECT COUNT(*) FROM "users"
=> 0

As you can see, the only version that had an unexpected behaviour was AR 7.0.x.

Now (v0.6.1)

ActiveRecord 7.0.x

/app # bundle exec appraisal ar-7.0 irb
>> BUNDLE_GEMFILE=/app/gemfiles/ar_7.0.gemfile bundle exec irb
/usr/local/lib/ruby/gems/3.4.0/gems/irb-1.14.3/exe/irb:7: warning: irb was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add irb to your Gemfile or gemspec to silence this warning.
/app/.irbrc:6: warning: benchmark was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add benchmark to your Gemfile or gemspec to silence this warning.
/usr/local/bundle/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/concern/logging.rb:1: warning: logger was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add logger to your Gemfile or gemspec to silence this warning.
Environment loaded: test
/usr/local/lib/ruby/3.4.0/irb/input-method.rb:278: warning: rdoc was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add rdoc to your Gemfile or gemspec to silence this warning.
irb(main):001> User.transaction { User.count } ; User.count 
D, [2025-07-02T16:38:34.470334 #353] DEBUG -- :   [PostgreSQLProxy Primary] TRANSACTION (0.1ms)  BEGIN
D, [2025-07-02T16:38:34.474092 #353] DEBUG -- :   [PostgreSQLProxy Primary] User Count (0.3ms)  SELECT COUNT(*) FROM "users"
D, [2025-07-02T16:38:34.475096 #353] DEBUG -- :   [PostgreSQLProxy Primary] TRANSACTION (0.1ms)  COMMIT
D, [2025-07-02T16:38:34.486241 #353] DEBUG -- :   [PostgreSQL Replica] User Count (0.4ms)  SELECT COUNT(*) FROM "users"
=> 0

ActiveRecord 7.1.x

/app # bundle exec appraisal ar-7.1 irb
>> BUNDLE_GEMFILE=/app/gemfiles/ar_7.1.gemfile bundle exec irb
/usr/local/lib/ruby/gems/3.4.0/gems/irb-1.14.3/exe/irb:7: warning: irb was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add irb to your Gemfile or gemspec to silence this warning.
/app/.irbrc:6: warning: benchmark was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add benchmark to your Gemfile or gemspec to silence this warning.
/usr/local/bundle/gems/activesupport-7.1.3.4/lib/active_support/logger_thread_safe_level.rb:4: warning: logger was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add logger to your Gemfile or gemspec to silence this warning.
Environment loaded: test
DEPRECATION WARNING: Support for `config.active_support.cache_format_version = 6.1` has been deprecated and will be removed in Rails 7.2.

Check the Rails upgrade guide at https://guides.rubyonrails.org/upgrading_ruby_on_rails.html#new-activesupport-cache-serialization-format
for more information on how to upgrade.
 (called from Class#new at /app/lib/active_record_proxy_adapters/cache_configuration.rb:28)
/usr/local/lib/ruby/3.4.0/irb/input-method.rb:278: warning: rdoc was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add rdoc to your Gemfile or gemspec to silence this warning.
irb(main):001> User.transaction { User.count } ; User.count 
D, [2025-07-02T16:39:00.866894 #368] DEBUG -- :   [PostgreSQLProxy Primary] TRANSACTION (0.1ms)  BEGIN
D, [2025-07-02T16:39:00.871306 #368] DEBUG -- :   [PostgreSQLProxy Primary] User Count (0.3ms)  SELECT COUNT(*) FROM "users"
D, [2025-07-02T16:39:00.872865 #368] DEBUG -- :   [PostgreSQLProxy Primary] TRANSACTION (0.1ms)  COMMIT
D, [2025-07-02T16:39:00.873785 #368] DEBUG -- :   [PostgreSQL Replica] User Count (0.6ms)  SELECT COUNT(*) FROM "users"
=> 0

ActiveRecord 7.2.x

/app # bundle exec appraisal ar-7.2 irb
>> BUNDLE_GEMFILE=/app/gemfiles/ar_7.2.gemfile bundle exec irb
/usr/local/lib/ruby/gems/3.4.0/gems/irb-1.14.3/exe/irb:7: warning: irb was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add irb to your Gemfile or gemspec to silence this warning.
Environment loaded: test
/usr/local/lib/ruby/3.4.0/irb/input-method.rb:278: warning: rdoc was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add rdoc to your Gemfile or gemspec to silence this warning.
irb(main):001> User.transaction { User.count } ; User.count 
D, [2025-07-02T16:39:28.780619 #392] DEBUG -- :   [PostgreSQLProxy Primary] TRANSACTION (0.1ms)  BEGIN
D, [2025-07-02T16:39:28.784857 #392] DEBUG -- :   [PostgreSQLProxy Primary] User Count (0.3ms)  SELECT COUNT(*) FROM "users"
D, [2025-07-02T16:39:28.786559 #392] DEBUG -- :   [PostgreSQLProxy Primary] TRANSACTION (0.1ms)  COMMIT
D, [2025-07-02T16:39:28.787424 #392] DEBUG -- :   [PostgreSQL Replica] User Count (0.5ms)  SELECT COUNT(*) FROM "users"
=> 0

ActiveRecord 8.0.x

/app # bundle exec appraisal ar-8.0 irb
>> BUNDLE_GEMFILE=/app/gemfiles/ar_8.0.gemfile bundle exec irb
/usr/local/lib/ruby/gems/3.4.0/gems/irb-1.14.3/exe/irb:7: warning: irb was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add irb to your Gemfile or gemspec to silence this warning.
Environment loaded: test
/usr/local/lib/ruby/3.4.0/irb/input-method.rb:278: warning: rdoc was loaded from the standard library, but will no longer be part of the default gems starting from Ruby 3.5.0.
You can add rdoc to your Gemfile or gemspec to silence this warning.
irb(main):001> User.transaction { User.count } ; User.count 
D, [2025-07-02T16:40:04.527768 #407] DEBUG -- :   [PostgreSQLProxy Primary] TRANSACTION (0.1ms)  BEGIN
D, [2025-07-02T16:40:04.528250 #407] DEBUG -- :   [PostgreSQLProxy Primary] User Count (0.6ms)  SELECT COUNT(*) FROM "users"
D, [2025-07-02T16:40:04.529607 #407] DEBUG -- :   [PostgreSQLProxy Primary] TRANSACTION (0.1ms)  COMMIT
D, [2025-07-02T16:40:04.541124 #407] DEBUG -- :   [PostgreSQL Replica] User Count (9.8ms)  SELECT COUNT(*) FROM "users"
=> 0

All versions behave the same way now.

I think that is sufficient evidence to say the issue has been resolved.
There might be something else at play here outside the scope of this gem that could explain the behaviour you're seeing in 7.1.x.
So I suggest you investigate further and, if you can share a reproducible environment, I can reopen the topic. Otherwise, it will remain closed.