Add compatibility with Fiber-safe ConnectionPool in Rails 7.1

[swrobel]

Rails 7.1 added opt-in config.active_support.isolation_level = :fiber in rails/rails#44219 to replace Threads with more modern Fiber-based concurrency primitives that are available in 3.x versions of Ruby, but unfortunately appmap seems to cause conflicts with this setting that prevents database connections from being released to the pool, resulting in:

could not obtain a connection from the pool within 5.000 seconds (waited 5.004 seconds); all pooled connections were in use
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:128:in `block in wait_poll'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:117:in `loop'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:117:in `wait_poll'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:78:in `internal_poll'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:204:in `internal_poll'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:73:in `block in poll'
/opt/homebrew/Cellar/ruby/3.2.2_1/lib/ruby/3.2.0/monitor.rb:202:in `synchronize'
/opt/homebrew/Cellar/ruby/3.2.2_1/lib/ruby/3.2.0/monitor.rb:202:in `mon_synchronize'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:82:in `synchronize'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:73:in `poll'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:661:in `acquire_connection'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:355:in `checkout'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:184:in `connection'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_handler.rb:246:in `retrieve_connection'
gems/activerecord-7.1.2/lib/active_record/connection_handling.rb:287:in `retrieve_connection'
gems/activerecord-7.1.2/lib/active_record/connection_handling.rb:254:in `connection'
gems/appmap-0.103.0/lib/appmap/handler/rails/sql_handler.rb:135:in `in_transaction?'
gems/appmap-0.103.0/lib/appmap/handler/rails/sql_handler.rb:49:in `examine'
gems/appmap-0.103.0/lib/appmap/handler/rails/sql_handler.rb:158:in `call'
gems/activesupport-7.1.2/lib/active_support/notifications/fanout.rb:137:in `block in finish'
gems/activesupport-7.1.2/lib/active_support/notifications/fanout.rb:26:in `block in iterate_guarding_exceptions'
gems/activesupport-7.1.2/lib/active_support/notifications/fanout.rb:25:in `each'
gems/activesupport-7.1.2/lib/active_support/notifications/fanout.rb:25:in `iterate_guarding_exceptions'
gems/activesupport-7.1.2/lib/active_support/notifications/fanout.rb:125:in `each'
gems/activesupport-7.1.2/lib/active_support/notifications/fanout.rb:136:in `finish'
gems/activesupport-7.1.2/lib/active_support/notifications/fanout.rb:262:in `block in finish_with_values'
gems/activesupport-7.1.2/lib/active_support/notifications/fanout.rb:26:in `block in iterate_guarding_exceptions'
gems/activesupport-7.1.2/lib/active_support/notifications/fanout.rb:25:in `each'
gems/activesupport-7.1.2/lib/active_support/notifications/fanout.rb:25:in `iterate_guarding_exceptions'
gems/activesupport-7.1.2/lib/active_support/notifications/fanout.rb:261:in `finish_with_values'
gems/activesupport-7.1.2/lib/active_support/notifications/fanout.rb:254:in `finish'
gems/activesupport-7.1.2/lib/active_support/notifications/instrumenter.rb:64:in `instrument'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract_adapter.rb:1143:in `log'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/postgresql/database_statements.rb:53:in `raw_execute'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/database_statements.rb:521:in `internal_execute'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/postgresql/schema_statements.rb:245:in `client_min_messages='
gems/activerecord-7.1.2/lib/active_record/connection_adapters/postgresql_adapter.rb:1001:in `configure_connection'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract_adapter.rb:744:in `reset!'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/postgresql_adapter.rb:377:in `block in reset!'
gems/activesupport-7.1.2/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/postgresql_adapter.rb:369:in `reset!'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:426:in `block in reap'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:424:in `each'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:424:in `reap'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:660:in `acquire_connection'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:355:in `checkout'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:184:in `connection'
gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/connection_handler.rb:246:in `retrieve_connection'
gems/activerecord-7.1.2/lib/active_record/connection_handling.rb:287:in `retrieve_connection'
gems/activerecord-7.1.2/lib/active_record/connection_handling.rb:254:in `connection'
gems/activerecord-7.1.2/lib/active_record/core.rb:362:in `cached_find_by_statement'
gems/activerecord-7.1.2/lib/active_record/core.rb:404:in `cached_find_by'
gems/activerecord-7.1.2/lib/active_record/core.rb:285:in `find_by'
gems/ar_lazy_preload-1.1.2/lib/ar_lazy_preload/active_record/base.rb:35:in `find_by'
gems/activerecord-7.1.2/lib/active_record/secure_password.rb:51:in `authenticate_by'
app/graphql/mutations/create_session.rb:45:in `authenticate_refresh_token'
gems/appmap-0.103.0/lib/appmap/hook/method/ruby3.rb:44:in `bind_call'
gems/appmap-0.103.0/lib/appmap/hook/method/ruby3.rb:44:in `do_call'
gems/appmap-0.103.0/lib/appmap/hook/method/ruby3.rb:53:in `trace_call'
gems/appmap-0.103.0/lib/appmap/hook/method/ruby3.rb:20:in `call'
gems/appmap-0.103.0/lib/appmap/hook/method/ruby3.rb:70:in `block in hook_method_def'
gems/skylight-6.0.1/lib/skylight/helpers.rb:184:in `authenticate_refresh_token'
app/graphql/mutations/create_session.rb:19:in `resolve'
gems/appmap-0.103.0/lib/appmap/hook/method/ruby3.rb:44:in `bind_call'
gems/appmap-0.103.0/lib/appmap/hook/method/ruby3.rb:44:in `do_call'
gems/appmap-0.103.0/lib/appmap/hook/method/ruby3.rb:53:in `trace_call'
gems/appmap-0.103.0/lib/appmap/hook/method/ruby3.rb:20:in `call'
gems/appmap-0.103.0/lib/appmap/hook/method/ruby3.rb:70:in `block in hook_method_def'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/resolver.rb:107:in `public_send'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/resolver.rb:107:in `block (3 levels) in resolve_with_support'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:770:in `minimal_after_lazy'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/query.rb:372:in `after_lazy'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/resolver.rb:94:in `block (2 levels) in resolve_with_support'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:770:in `minimal_after_lazy'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/query.rb:372:in `after_lazy'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/resolver.rb:85:in `block in resolve_with_support'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:770:in `minimal_after_lazy'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/query.rb:372:in `after_lazy'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/resolver.rb:73:in `resolve_with_support'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/has_single_input_argument.rb:36:in `resolve_with_support'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/relay_classic_mutation.rb:45:in `resolve_with_support'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/field.rb:698:in `public_send'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/field.rb:698:in `block (2 levels) in resolve'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/field.rb:832:in `with_extensions'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/field.rb:669:in `block in resolve'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:770:in `minimal_after_lazy'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/query.rb:372:in `after_lazy'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/field.rb:667:in `resolve'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:358:in `block (2 levels) in evaluate_selection_with_resolved_keyword_args'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/tracing/trace.rb:52:in `execute_field'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:357:in `block in evaluate_selection_with_resolved_keyword_args'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:709:in `call_method_on_directives'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:354:in `evaluate_selection_with_resolved_keyword_args'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:331:in `block in evaluate_selection_with_args'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:830:in `after_lazy'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:279:in `evaluate_selection_with_args'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/runtime.rb:273:in `block in evaluate_selection'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/execution/interpreter/arguments_cache.rb:51:in `block in dataload_for'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/schema/member/has_arguments.rb:300:in `block (3 levels) in coerce_arguments'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/dataloader.rb:262:in `block in spawn_job_fiber'
bundler/gems/graphql-ruby-becd60008606/lib/graphql/dataloader.rb:230:in `block in spawn_fiber'

[kgilpin]

Hi thanks for reporting this. The test suite contains a fixture app of Rails 7 so hopefully if we switch this on it will be easy to reproduce.

[swrobel]

Hi thanks for reporting this. The test suite contains a fixture app of Rails 7 so hopefully if we switch this on it will be easy to reproduce.

I should note this happens after 6 requests in sequence, assuming they each make one database query, or I believe a single request that makes 6 or more queries. Assuming pool size is the rails default of 5

[kgilpin]

@apotterri this could be worth a look?

[kgilpin]

A workaround would be to stick with thread-based isolation when (a) in development and (b) AppMap is enabled.

[coderberry]

@swrobel Would you mind providing some extra info on your Rails app configuration so we can easily replicate the issue?

From your backtrace, I see that you are using Rails 7.1.2 and GraphQL.

Some questions:

1. What database are you using?
2. Are your tests leading to the error above? If so, can you describe the test?
3. Any extra info that you might find helpful in replicating the error

Thanks!

[swrobel]

@coderberry

1. PostgreSQL
2. I have not been able to reproduce in a test. This happens when running gql queries against my api, which is using graphql-ruby. I'm using Altair GraphQL client to send the same request 6 times in a row, and on the 6th, I get the all pooled connections in use exception noted above. This does not happen when I don't have the fiber connection pool enabled.

[coderberry]

@coderberry

1. PostgreSQL
2. I have not been able to reproduce in a test. This happens when running gql queries against my api, which is using graphql-ruby. I'm using Altair GraphQL client to send the same request 6 times in a row, and on the 6th, I get the all pooled connections in use exception noted above. This does not happen when I don't have the fiber connection pool enabled.

Thank you for this information. I have created an article on creating a GraphQL Rails app that will hopefully mimic what you have built (see Load Testing GraphQL with Rails)

I will download and test with Altair. Thanks for the link!

You mentioned that you submitted the request 6 times in a row. Was that simply pressing the button again and again quickly? If so, are the queries that are being executed pretty large?

Thanks!

[swrobel]

Was that simply pressing the button again and again quickly?

Correct

If so, are the queries that are being executed pretty large?

I wouldn't say so. I'm able to do the same indefinitely when I don't have appmap in my gemfile, or I don't have the fiber pool enabled.

[coderberry]

@swrobel Gotcha. Are you running a fiber-based server or job processor (any of these)? I am still unable to replicate this issue.

source

I wouldn't say so. I'm able to do the same indefinitely when I don't have appmap in my gemfile, or I don't have the fiber pool enabled.

Does this happen without the AppMap gem but with fiber pool enabled?

[swrobel]

Does this happen without the AppMap gem but with fiber pool enabled?

No it does not. I'm using Puma. I've never tried falcon.

[coderberry]

@swrobel Which version or Ruby are you using?

[swrobel]

@coderberry 3.3.0

[coderberry]

This issue is being discussed here: rmosolgo/graphql-ruby#4874.