jruby/activerecord-jdbc-adapter — Issue #145: ActiveRecord::JDBCError: SAVEPOINT active_record_1 does not exist: RELEASE SAVEPOINT active_record_1
Author: d01
Created: 2011-12-09 20:51:17+00:00
State: open

Using Rails 3.0/3.1, Jruby 1.6.5, Warbler 1.3.2, and activerecord-jdbcmysql-adapter 1.2.1. and 1.2.0. Config.threadsafe! and Tomcat 7.0.23. Mysql 5.1.54.

When tested manually I find no problems. But when running concurrent threads in JMeter, I begin to see the following error:

ActiveRecord::JDBCError: SAVEPOINT active_record_1 does not exist: RELEASE SAVEPOINT active_record_1

It emanates highly intermittently from a variety of activerecord method calls; so far, anything that creates a transaction internally. save! etc. Sometimes I can get several in a matter of minutes; other times it might take an hour to get one.

We use no explicit transactions within our code at all, so the firing of savepoint behavior within database_statements.rb (i.e. 182) is already worrying. We have confirmed that savepoints are never created during manual runs of our code via mysql general_log.

Suffice it to say, either in some inexplicable way a savepoint does need to be created once in a blue moon, but is then released or lost on mysql's end, or, far more likely, some awfully discouraging threadsafety bug within jruby and/or activerecord-jdbcmysql-adapter is causing the DatabaseStatements module to have open_transactions > 0 when it should not be.

Stack trace 1 (full for completeness sake):

arjdbc/jdbc/RubyJdbcConnection.java:191:in `execute'
tmp/exploded/WEB-INF/gems/gems/activerecord-jdbc-adapter-1.2.1/lib/arjdbc/jdbc/adapter.rb:216:in `_execute'
tmp/exploded/WEB-INF/gems/gems/activerecord-jdbc-adapter-1.2.1/lib/arjdbc/jdbc/adapter.rb:208:in `execute'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:244:in `log'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:239:in `log'
tmp/exploded/WEB-INF/gems/gems/activerecord-jdbc-adapter-1.2.1/lib/arjdbc/jdbc/adapter.rb:208:in `execute'
tmp/exploded/WEB-INF/gems/gems/activerecord-jdbc-adapter-1.2.1/lib/arjdbc/mysql/adapter.rb:160:in `release_savepoint'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:220:in `transaction'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/transactions.rb:208:in `transaction'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/transactions.rb:293:in `with_transaction_returning_status'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/transactions.rb:241:in `save'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/transactions.rb:252:in `rollback_active_record_state!'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/transactions.rb:240:in `save'
......
org/jruby/RubyBasicObject.java:1688:in `__send__'
org/jruby/RubyKernel.java:2114:in `send'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/abstract_controller/base.rb:167:in `process_action'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_controller/metal/rendering.rb:10:in `process_action'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/abstract_controller/callbacks.rb:18:in `process_action'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/callbacks.rb:438:in `_run__175321545__process_action__604165721__callbacks'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/callbacks.rb:217:in `_conditional_callback_around_613'
......
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/callbacks.rb:216:in `_conditional_callback_around_613'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/callbacks.rb:419:in `_run__175321545__process_action__604165721__callbacks'
org/jruby/RubyBasicObject.java:1688:in `__send__'
org/jruby/RubyKernel.java:2114:in `send'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/callbacks.rb:401:in `_run_process_action_callbacks'
org/jruby/RubyBasicObject.java:1694:in `__send__'
org/jruby/RubyKernel.java:2118:in `send'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/callbacks.rb:81:in `run_callbacks'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/abstract_controller/callbacks.rb:17:in `process_action'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_controller/metal/rescue.rb:17:in `process_action'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/notifications.rb:53:in `instrument'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/notifications.rb:53:in `instrument'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_controller/metal/instrumentation.rb:29:in `process_action'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_controller/metal/params_wrapper.rb:201:in `process_action'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/abstract_controller/base.rb:121:in `process'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/abstract_controller/rendering.rb:45:in `process'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_controller/metal.rb:193:in `dispatch'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_controller/metal/rack_delegation.rb:14:in `dispatch'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_controller/metal.rb:236:in `action'
org/jruby/RubyProc.java:258:in `call'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_dispatch/routing/route_set.rb:65:in `dispatch'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_dispatch/routing/route_set.rb:29:in `call'
tmp/exploded/WEB-INF/gems/gems/rack-mount-0.8.3/lib/rack/mount/route_set.rb:152:in `call'
tmp/exploded/WEB-INF/gems/gems/rack-mount-0.8.3/lib/rack/mount/code_generation.rb:114:in `recognize'
tmp/exploded/WEB-INF/gems/gems/rack-mount-0.8.3/lib/rack/mount/code_generation.rb:73:in `optimized_each'
tmp/exploded/WEB-INF/gems/gems/rack-mount-0.8.3/lib/rack/mount/code_generation.rb:113:in `recognize'
tmp/exploded/WEB-INF/gems/gems/rack-mount-0.8.3/lib/rack/mount/route_set.rb:141:in `call'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_dispatch/routing/route_set.rb:532:in `call'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'
tmp/exploded/WEB-INF/gems/gems/rack-1.3.5/lib/rack/etag.rb:23:in `call'
tmp/exploded/WEB-INF/gems/gems/rack-1.3.5/lib/rack/conditionalget.rb:35:in `call'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_dispatch/middleware/head.rb:14:in `call'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_dispatch/middleware/params_parser.rb:21:in `call'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_dispatch/middleware/flash.rb:247:in `call'
tmp/exploded/WEB-INF/gems/gems/rack-1.3.5/lib/rack/session/abstract/id.rb:195:in `context'
tmp/exploded/WEB-INF/gems/gems/rack-1.3.5/lib/rack/session/abstract/id.rb:190:in `call'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_dispatch/middleware/cookies.rb:331:in `call'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/query_cache.rb:64:in `call'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:477:in `call'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_dispatch/middleware/callbacks.rb:29:in `call'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/callbacks.rb:407:in `_run_call_callbacks'
org/jruby/RubyBasicObject.java:1688:in `__send__'
org/jruby/RubyKernel.java:2114:in `send'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/callbacks.rb:81:in `run_callbacks'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_dispatch/middleware/callbacks.rb:28:in `call'
tmp/exploded/WEB-INF/gems/gems/rack-1.3.5/lib/rack/sendfile.rb:101:in `call'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_dispatch/middleware/remote_ip.rb:48:in `call'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_dispatch/middleware/show_exceptions.rb:47:in `call'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/railties/lib/rails/rack/logger.rb:13:in `call'
tmp/exploded/WEB-INF/gems/gems/rack-1.3.5/lib/rack/methodoverride.rb:24:in `call'
tmp/exploded/WEB-INF/gems/gems/rack-1.3.5/lib/rack/runtime.rb:17:in `call'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/cache/strategy/local_cache.rb:72:in `call'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/actionpack/lib/action_dispatch/middleware/static.rb:53:in `call'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/railties/lib/rails/engine.rb:456:in `call'
file:tmp/exploded/WEB-INF/lib/jruby-rack-1.1.1.jar!/rack/handler/servlet.rb:19:in `call'

Stack trace 2 (rest omitted for clarity):

arjdbc/jdbc/RubyJdbcConnection.java:191:in `execute'
tmp/exploded/WEB-INF/gems/gems/activerecord-jdbc-adapter-1.2.1/lib/arjdbc/jdbc/adapter.rb:216:in `_execute'
tmp/exploded/WEB-INF/gems/gems/activerecord-jdbc-adapter-1.2.1/lib/arjdbc/jdbc/adapter.rb:208:in `execute'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:244:in `log'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:239:in `log'
tmp/exploded/WEB-INF/gems/gems/activerecord-jdbc-adapter-1.2.1/lib/arjdbc/jdbc/adapter.rb:208:in `execute'
tmp/exploded/WEB-INF/gems/gems/activerecord-jdbc-adapter-1.2.1/lib/arjdbc/mysql/adapter.rb:156:in `rollback_to_savepoint'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `transaction'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:224:in `transaction'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/transactions.rb:208:in `transaction'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/transactions.rb:293:in `with_transaction_returning_status'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/transactions.rb:241:in `save'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/transactions.rb:252:in `rollback_active_record_state!'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/transactions.rb:240:in `save'
......

Stack trace 3, for ActiveRecord::JDBCError: SAVEPOINT active_record_1 does not exist: ROLLBACK TO SAVEPOINT active_record_1:

gems/gems/activerecord-3.0.10/lib/active_record/connection_adapters/abstract_adapter.rb:207:in `log'
gems/gems/activerecord-3.0.10/lib/active_record/connection_adapters/abstract_adapter.rb:200:in `log'
gems/gems/activerecord-jdbc-adapter-1.2.1/lib/arjdbc/jdbc/adapter.rb:208:in `execute'
gems/gems/activerecord-jdbc-adapter-1.2.1/lib/arjdbc/mysql/adapter.rb:156:in `rollback_to_savepoint'
gems/gems/activerecord-3.0.10/lib/active_record/connection_adapters/abstract/database_statements.rb:179:in `transaction'
gems/gems/activerecord-3.0.10/lib/active_record/connection_adapters/abstract/database_statements.rb:171:in `transaction'
gems/gems/activerecord-3.0.10/lib/active_record/transactions.rb:207:in `transaction'
gems/gems/activerecord-3.0.10/lib/active_record/transactions.rb:290:in `with_transaction_returning_status'
gems/gems/activerecord-3.0.10/lib/active_record/transactions.rb:240:in `save'
gems/gems/activerecord-3.0.10/lib/active_record/transactions.rb:251:in `rollback_active_record_state!'
gems/gems/activerecord-3.0.10/lib/active_record/transactions.rb:239:in `save'
......

It's unclear why that rolled back in the first place, by the way.

Stack trace 4:

arjdbc/jdbc/RubyJdbcConnection.java:191:in `execute'
tmp/exploded/WEB-INF/gems/gems/activerecord-jdbc-adapter-1.2.1/lib/arjdbc/jdbc/adapter.rb:216:in `_execute'
tmp/exploded/WEB-INF/gems/gems/activerecord-jdbc-adapter-1.2.1/lib/arjdbc/jdbc/adapter.rb:208:in `execute'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:244:in `log'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activesupport/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:239:in `log'
tmp/exploded/WEB-INF/gems/gems/activerecord-jdbc-adapter-1.2.1/lib/arjdbc/jdbc/adapter.rb:208:in `execute'
tmp/exploded/WEB-INF/gems/gems/activerecord-jdbc-adapter-1.2.1/lib/arjdbc/mysql/adapter.rb:160:in `release_savepoint'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:220:in `transaction'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/transactions.rb:208:in `transaction'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/transactions.rb:293:in `with_transaction_returning_status'
tmp/exploded/WEB-INF/gems/bundler/gems/rails-9203890100c8/activerecord/lib/active_record/transactions.rb:246:in `save!'
......