Search code examples
mysqlruby-on-railsactiverecordout-of-memorydisconnect

Rails loses connection to MySQL


When doing normal database queries with ActiveRecord I encounter following errors:

Mysql2::Error: Lost connection to MySQL server during query

or even

ActiveRecord::StatementInvalid (Mysql2::Error: MySQL client ran out of memory)

The errors are non-recoverable (reconnect is possible by app restart only) and aren't bound to specific database query (they pop up suddenly in various places of app).

The application is not high-loaded. Actually I am the only user of it.

Sometimes the application runs a whole night without any trouble, sometimes it crashes after several hours/minutes of operation. Sometimes WEBrick/Puma exit suddenly with some exit code without any MySQL errors before.

I tried to upgrade Rails from 4.0.4 to later version, tried to downgrade MySQL from 5.6 to 5.5, tried to change mysql2 gem version - nothing helped.

  1. It couldn't be a network connectivity trouble because MySQL runs on the same machine and is accessed through localhost name.

  2. The database doesn't store millions of rows and none of queries returns repeated rows.

  3. I am not sure about initial connection because I honestly don't know whether Rails is reusing an existing connection for several queries or creating the new one for each query. It cannot be a long distance or slow connection because it is localhost.

Questions:

  1. How did I manage to run into the situation?

  2. What to do to resolve the problem?

Here is a piece of log:

  Driver Load (0.0ms) SELECT `drivers`.* FROM `drivers` WHERE `drivers`.`ts_id` = 1
  WorkShift Load (1.0ms) SELECT `work_shifts`.* FROM `work_shifts` WHERE `work_shifts`.`driver_id` = 1 AND `work_shifts`.`current_state` = 1 ORDER BY `work_shifts`.`scheduled_opened_at` DESC LIMIT 1
  Trip Load (1.0ms) SELECT `trips`.* FROM `trips` WHERE `trips`.`work_shift_id` = 1 AND (current_state in (3,4,5,9)) ORDER BY `trips`.`id` ASC LIMIT 1
Mysql2::Error: Lost connection to MySQL server during query: SELECT  `trips`.* FROM `trips`  WHERE `trips`.`work_shift_id` = 1 AND (current_state in (3,4,5,9))  ORDER BY `trips`.`id` ASC LIMIT 1
2014-10-11 22:56:30 UpCloud(1).send_driver_statuses: Exception(ActiveRecord::StatementInvalid): Mysql2::Error: Lost connection to MySQL server during query: SELECT  `trips`.* FROM `trips`  WHERE `trips`.`work_shift_id` = 1 AND (current_state in (3,4,5,9))  ORDER BY `trips`.`id` ASC LIMIT 1

==== Stack trace: ====
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `query'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `block in execute'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_adapter.rb:442:in `block in log'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activesupport-4.0.4/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_adapter.rb:437:in `log'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `execute'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/mysql2_adapter.rb:222:in `execute'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/mysql2_adapter.rb:226:in `exec_query'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/mysql2_adapter.rb:235:in `select'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract/database_statements.rb:32:in `select_all'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract/query_cache.rb:63:in `select_all'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/querying.rb:36:in `find_by_sql'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/relation.rb:585:in `exec_queries'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/association_relation.rb:15:in `exec_queries'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/relation.rb:471:in `load'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/relation.rb:220:in `to_a'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/relation/finder_methods.rb:326:in `find_first'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/relation/finder_methods.rb:91:in `first'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-deprecated_finders-1.0.3/lib/active_record/deprecated_finders/relation.rb:129:in `first'
D:/Work/disp/lib/ex/up_cloud.rb:365:in `up_driver_status'
D:/Work/disp/lib/ex/up_cloud.rb:416:in `block (4 levels) in send_driver_statuses'
C:in `each'
C:in `each'
D:/Work/disp/lib/ex/up_cloud.rb:415:in `block (3 levels) in send_driver_statuses'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/nokogiri-1.6.3.1-x86-mingw32/lib/nokogiri/xml/builder.rb:391:in `call'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/nokogiri-1.6.3.1-x86-mingw32/lib/nokogiri/xml/builder.rb:391:in `insert'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/nokogiri-1.6.3.1-x86-mingw32/lib/nokogiri/xml/builder.rb:375:in `method_missing'
D:/Work/disp/lib/ex/up_cloud.rb:414:in `block (2 levels) in send_driver_statuses'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/nokogiri-1.6.3.1-x86-mingw32/lib/nokogiri/xml/builder.rb:391:in `call'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/nokogiri-1.6.3.1-x86-mingw32/lib/nokogiri/xml/builder.rb:391:in `insert'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/nokogiri-1.6.3.1-x86-mingw32/lib/nokogiri/xml/builder.rb:375:in `method_missing'
D:/Work/disp/lib/ex/up_cloud.rb:413:in `block in send_driver_statuses'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/nokogiri-1.6.3.1-x86-mingw32/lib/nokogiri/xml/builder.rb:293:in `initialize'
D:/Work/disp/lib/ex/up_cloud.rb:412:in `new'
D:/Work/disp/lib/ex/up_cloud.rb:412:in `send_driver_statuses'
D:/Work/disp/lib/ex/up_cloud.rb:73:in `block in initialize'
  Driver Load (1.0ms) SELECT drivers.id, work_shifts.latitude, work_shifts.longitude, work_shifts.updated_at FROM `drivers` INNER JOIN `work_shifts` ON `work_shifts`.`driver_id` = `drivers`.`id` WHERE `drivers`.`ts_id` = 1 AND `work_shifts`.`current_state` = 1
Mysql2::Error: MySQL client ran out of memory: SELECT `orders`.* FROM `orders`  WHERE `orders`.`current_state` = 2
2014-10-11 22:56:32 Postman.postman thread: Exception(ActiveRecord::StatementInvalid): Mysql2::Error: MySQL client ran out of memory: SELECT `orders`.* FROM `orders`  WHERE `orders`.`current_state` = 2

==== Stack trace: ====
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `query'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `block in execute'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_adapter.rb:442:in `block in log'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activesupport-4.0.4/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_adapter.rb:437:in `log'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `execute'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/mysql2_adapter.rb:222:in `execute'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/mysql2_adapter.rb:226:in `exec_query'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/mysql2_adapter.rb:235:in `select'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract/database_statements.rb:32:in `select_all'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/connection_adapters/abstract/query_cache.rb:63:in `select_all'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/querying.rb:36:in `find_by_sql'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/relation.rb:585:in `exec_queries'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/relation.rb:471:in `load'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/relation.rb:220:in `to_a'
C:/Ruby200/lib/ruby/gems/2.0.0/gems/activerecord-4.0.4/lib/active_record/relation.rb:565:in `blank?'
D:/Work/disp/lib/postman.rb:31:in `do_posting'
D:/Work/disp/lib/postman.rb:16:in `block (2 levels) in initialize'
D:/Work/disp/lib/advanced_logging.rb:8:in `with_level'
D:/Work/disp/lib/postman.rb:15:in `block in initialize'

Solution

  • The problem was executing database queries in different threads without proper threads synchronization.