4

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'
Paul
  • 25,812
  • 38
  • 124
  • 247
  • 1
    From mysql docs, there are a few possible explanations: http://dev.mysql.com/doc/refman/5.6/en/error-lost-connection.html – rossta Oct 12 '14 at 11:24
  • I wonder what was the query that resulted in this, and if it can be solved by using `find_each` or the likes. – D-side Oct 12 '14 at 11:42
  • @D-side: randomly chosen query. – Paul Oct 12 '14 at 11:43
  • @Paul An example from the logs (just before this error kicks in) might probably help. Other than that, I don't see how this could happen. – D-side Oct 12 '14 at 11:45
  • @Paul Not intending to start an OS argument here, but... try testing your app in a virtual machine loaded with Linux, just about any flavor (Ubuntu is fine). It might be that MySQL client (or something else) is buggy and/or outdated in your environment. – D-side Oct 12 '14 at 20:38
  • @D-side: I knew that somebody will mention this argument, but no, these problems appear in CentOS 6.5 too (except out of memory). – Paul Oct 13 '14 at 06:33
  • @Paul then you should have mentioned that in your question. – D-side Oct 13 '14 at 06:36

1 Answers1

0

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

Paul
  • 25,812
  • 38
  • 124
  • 247