Rake task hang on mysql client

[frankchendev]

ruby-2.3.1, rake (12.0.0), mysql2 (0.4.6)
Rake task was running on docker container (docker OS: Debian GNU/Linux 8, host OS: Linux e5838ca89d6e 4.4.51-40.58.amzn1.x86_64 #1 SMP Tue Feb 28 21:57:17 UTC 2017 x86_64 GNU/Linux) as AWS ECS task, the database server is Aurora MySQL 5.6.10a in AWS RDS.

The task task would hung arbitrary on the queries which was executed by mysql client. After hunging, there was no GC activity, and CPU usage was very low too. The thread profiling was collected through NewRelic. There were three thread was active, the first two thread were always there, but the third one was sometime showed, but some time not.

Is this thread deadlock or other issue?

thread 1
50% /usr/local/bin/bundle.

:23
50% /usr/local/bin/bundle.load :23
50% /usr/local/lib/ruby/gems/2.3.0/gems/bundler-1.12.5/exe/bundle.<top (required)> :19
50% /usr/local/lib/ruby/gems/2.3.0/gems/bundler-1.12.5/lib/bundler/friendly_errors.rb.with_friendly_errors :98
50% /usr/local/lib/ruby/gems/2.3.0/gems/bundler-1.12.5/exe/bundle.block in <top (required)> :27
50% /usr/local/lib/ruby/gems/2.3.0/gems/bundler-1.12.5/lib/bundler/cli.rb.start :11
50% /usr/local/lib/ruby/gems/2.3.0/gems/bundler-1.12.5/lib/bundler/vendor/thor/lib/thor/base.rb.start :440
50% /usr/local/lib/ruby/gems/2.3.0/gems/bundler-1.12.5/lib/bundler/vendor/thor/lib/thor.rb.dispatch :359
50% /usr/local/lib/ruby/gems/2.3.0/gems/bundler-1.12.5/lib/bundler/vendor/thor/lib/thor/invocation.rb.invoke_command :126
50% /usr/local/lib/ruby/gems/2.3.0/gems/bundler-1.12.5/lib/bundler/vendor/thor/lib/thor/command.rb.run :27
50% /usr/local/lib/ruby/gems/2.3.0/gems/bundler-1.12.5/lib/bundler/cli.rb.exec :304
50% /usr/local/lib/ruby/gems/2.3.0/gems/bundler-1.12.5/lib/bundler/cli/exec.rb.run :24
50% /usr/local/lib/ruby/gems/2.3.0/gems/bundler-1.12.5/lib/bundler/cli/exec.rb.kernel_load :63
50% /usr/local/lib/ruby/gems/2.3.0/gems/bundler-1.12.5/lib/bundler/cli/exec.rb.load :63
50% /usr/local/bundle/bin/rake.<top (required)> :17
50% /usr/local/bundle/bin/rake.load :17
50% /usr/local/bundle/gems/rake-12.0.0/exe/rake.<top (required)> :27
50% /usr/local/bundle/gems/rake-12.0.0/lib/rake/application.rb.run :77
50% /usr/local/bundle/gems/rake-12.0.0/lib/rake/application.rb.standard_exception_handling :178
50% /usr/local/bundle/gems/rake-12.0.0/lib/rake/application.rb.block in run :80
50% /usr/local/bundle/gems/rake-12.0.0/lib/rake/application.rb.top_level :102
50% /usr/local/bundle/gems/rake-12.0.0/lib/rake/application.rb.run_with_threads :117
50% /usr/local/bundle/gems/rake-12.0.0/lib/rake/application.rb.block in top_level :108
50% /usr/local/bundle/gems/rake-12.0.0/lib/rake/application.rb.each :108
50% /usr/local/bundle/gems/rake-12.0.0/lib/rake/application.rb.block (2 levels) in top_level :108
50% /usr/local/bundle/gems/rake-12.0.0/lib/rake/application.rb.invoke_task :152
50% /usr/local/bundle/gems/rake-12.0.0/lib/rake/task.rb.invoke :180
50% /usr/local/bundle/gems/rake-12.0.0/lib/rake/task.rb.invoke_with_call_chain :187
50% /usr/local/lib/ruby/2.3.0/monitor.rb.mon_synchronize :214
50% /usr/local/bundle/gems/rake-12.0.0/lib/rake/task.rb.block in invoke_with_call_chain :194
50% /usr/local/bundle/gems/rake-12.0.0/lib/rake/task.rb.execute :250
50% /usr/local/bundle/gems/rake-12.0.0/lib/rake/task.rb.each :250
50% /usr/local/bundle/gems/rake-12.0.0/lib/rake/task.rb.block in execute :250
50% /extranet/lib/tasks/bulksheet_import.rake.block (2 levels) in <top (required)> :5
50% /extranet/lib/bulksheets/import_worker.rb.work :6
50% /extranet/lib/worker.rb.work :14
50% /extranet/lib/worker.rb.loop :14
50% /extranet/lib/worker.rb.block in work :16
50% /extranet/lib/bulksheets/import_worker.rb.do_work :12
50% /extranet/app/models/bulksheet_import.rb.process :54
50% /extranet/app/models/bulksheet_import.rb.ct_process :102
50% /extranet/app/models/bulksheet_import_log.rb.elapsed_time :27
50% /extranet/app/models/bulksheet_import.rb.block in ct_process :115
50% /extranet/lib/bulksheets/importer.rb.import :44
50% /extranet/lib/bulksheets/importer.rb.process_non_bulk_rows :94
50% /extranet/app/models/bulksheet_import_log.rb.elapsed_time :27
50% /extranet/lib/bulksheets/importer.rb.block in process_non_bulk_rows :94
50% /extranet/lib/bulksheets/csv_processor.rb.process :20
50% /extranet/lib/bulksheets/bulksheet_csv.rb.foreach :19
50% /usr/local/lib/ruby/2.3.0/csv.rb.foreach :1130
50% /usr/local/lib/ruby/2.3.0/csv.rb.open :1282
50% /usr/local/lib/ruby/2.3.0/csv.rb.block in foreach :1131
50% /usr/local/lib/ruby/2.3.0/csv.rb.each :1748
50% /extranet/lib/bulksheets/csv_processor.rb.block in process :21
50% /extranet/lib/bulksheets/csv_processor.rb.fetch_row :52
50% /extranet/lib/bulksheets/non_bulk_csv_processor.rb.process_row :13
50% /extranet/app/bulksheet_rows/intent_target_bulksheet_row.rb.process_row :25
50% /extranet/app/bulksheet_rows/bulksheet_row.rb.process_row :176
50% /extranet/app/bulksheet_rows/flight_intent_target_bulksheet_row.rb.save_changes :92
50% /usr/local/bundle/gems/activerecord-4.2.6/lib/active_record/transactions.rb.save! :291
50% /usr/local/bundle/gems/activerecord-4.2.6/lib/active_record/transactions.rb.with_transaction_returning_status :348
50% /usr/local/bundle/gems/activerecord-4.2.6/lib/active_record/transactions.rb.transaction :220
50% /usr/local/bundle/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/database_statements.rb.transaction :213
50% /usr/local/bundle/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/transaction.rb.within_new_transaction :183
50% /usr/local/bundle/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/transaction.rb.begin_transaction :166
50% /usr/local/bundle/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/transaction.rb.new :166
50% /usr/local/bundle/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/transaction.rb.initialize :140
50% /usr/local/bundle/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract_mysql_adapter.rb.begin_db_transaction :321
50% /usr/local/bundle/gems/activerecord-4.2.6/lib/active_record/connection_adapters/mysql2_adapter.rb.execute :231
50% /usr/local/bundle/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract_mysql_adapter.rb.execute :305
50% /usr/local/bundle/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract_adapter.rb.log :466
50% /usr/local/bundle/gems/activesupport-4.2.6/lib/active_support/notifications/instrumenter.rb.instrument :20
50% /usr/local/bundle/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract_adapter.rb.block in log :472
50% /usr/local/bundle/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract_mysql_adapter.rb.block in execute :305
50% /usr/local/bundle/gems/mysql2-0.4.6/lib/mysql2/client.rb.query :119
50% /usr/local/bundle/gems/mysql2-0.4.6/lib/mysql2/client.rb.handle_interrupt :119
50% /usr/local/bundle/gems/mysql2-0.4.6/lib/mysql2/client.rb.block in query :120
50% /usr/local/bundle/gems/mysql2-0.4.6/lib/mysql2/client.rb._query :120

thread 2:
50% /usr/local/bundle/gems/stud-0.0.22/lib/stud/buffer.rb.block in buffer_initialize :110
50% /usr/local/bundle/gems/stud-0.0.22/lib/stud/buffer.rb.loop :110
50% /usr/local/bundle/gems/stud-0.0.22/lib/stud/buffer.rb.block (2 levels) in buffer_initialize :111
50% /usr/local/bundle/gems/stud-0.0.22/lib/stud/buffer.rb.sleep :111

thread 3:
0% /usr/local/lib/ruby/2.3.0/timeout.rb.block (2 levels) in timeout :84
0% /usr/local/lib/ruby

[sodabrew]

You cannot use the same MySQL connection handle in more than one thread at a time, because the connection is stateful (i.e. currently running a query, or transmitting data, in the middle of a transaction, etc.).

Besides that, I don't recognize anything from the backtrace as being obviously problematic.

[frankchendev]

@sodabrew : Could you tell me where you saw two threads handle one connection? It looks like that there is only thread 1 use the MySql connection. But of course, I didn't understand where the thread 2 and 3 came.

From GC and CPU usage, I suspected that there were thread dead lock, but the stacktrace didn't tell me anything about deadlock.

[sodabrew]

The threads may be coming from Stud's buffer flushing: https://github.com/jordansissel/ruby-stud/blob/master/lib/stud/buffer.rb

But as long as there is only one thread executing queries this is not a problem.

[frankchendev]

We found the issue, but don't know what is root cause yet. We use a single connection to execute ~100k transactions, and the database stop response after 10k transactions. I tested to close and reconnect to database every other 1000 transactions, then it works fine. Basically I used ActiveRecord::Base.connection_pool.disconnect! to reconnect to database. Is any better way to refresh the connection?