Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

mysql2 doesn't seem to be threadsafe #461

Closed
bwalex opened this issue Dec 16, 2013 · 19 comments
Closed

mysql2 doesn't seem to be threadsafe #461

bwalex opened this issue Dec 16, 2013 · 19 comments
Milestone

Comments

@bwalex
Copy link

bwalex commented Dec 16, 2013

Running the code in https://github.com/bwalex/ar_threads with the mysql2 adapter (just adapt config/database.yml) and puma results in a fair number of random-looking failures:

<NoMethodError: undefined method `fields' for nil:NilClass>

Sometimes even a segfault:

*** Error in `puma: cluster worker: 27456': double free or corruption (out): 0x00007f8e1c001920 ***
======= Backtrace: =========
/usr/lib/libc.so.6(+0x72e5f)[0x7f8e7d6cee5f]
/usr/lib/libc.so.6(+0x7862e)[0x7f8e7d6d462e]
/usr/lib/libc.so.6(+0x79307)[0x7f8e7d6d5307]
/usr/lib/libmysqlclient.so.18(vio_delete+0x27)[0x7f8e78577ff7]
/usr/lib/libmysqlclient.so.18(end_server+0x3a)[0x7f8e785513ba]
/usr/lib/libmysqlclient.so.18(cli_safe_read+0x208)[0x7f8e78551688]
/usr/lib/libmysqlclient.so.18(cli_advanced_command+0x143)[0x7f8e78555ea3]
/usr/lib/libmysqlclient.so.18(mysql_ping+0x31)[0x7f8e7854ca41]
/usr/lib/ruby/gems/2.0.0/gems/mysql2-0.3.14/lib/mysql2/mysql2.so(+0x6459)[0x7f8e78a1e459]
/usr/lib/libruby.so.2.0(+0x180815)[0x7f8e7db87815]
/usr/lib/libruby.so.2.0(+0x1618f4)[0x7f8e7db688f4]
/usr/lib/libruby.so.2.0(+0x164dcc)[0x7f8e7db6bdcc]
/usr/lib/libruby.so.2.0(+0x169af7)[0x7f8e7db70af7]
/usr/lib/libruby.so.2.0(+0x16a624)[0x7f8e7db71624]
/usr/lib/libruby.so.2.0(+0x16b9ae)[0x7f8e7db729ae]
/usr/lib/libruby.so.2.0(rb_yield+0x9a4)[0x7f8e7db792e4]
/usr/lib/libruby.so.2.0(+0x3420d)[0x7f8e7da3b20d]
/usr/lib/libruby.so.2.0(+0x1618f4)[0x7f8e7db688f4]
/usr/lib/libruby.so.2.0(+0x16e30e)[0x7f8e7db7530e]
/usr/lib/libruby.so.2.0(+0x164d55)[0x7f8e7db6bd55]
/usr/lib/libruby.so.2.0(+0x169af7)[0x7f8e7db70af7]
ActiveRecord::StatementInvalid - Mysql2::Error: Lost connection to MySQL server during query: SELECT `tests`.* FROM `tests`:
        /usr/lib/ruby/gems/2.0.0/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `query'
        /usr/lib/ruby/gems/2.0.0/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `block in e
xecute'
        /usr/lib/ruby/gems/2.0.0/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract_adapter.rb:435:in `block in log'
        /usr/lib/ruby/gems/2.0.0/gems/activesupport-4.0.2/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
        /usr/lib/ruby/gems/2.0.0/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract_adapter.rb:430:in `log'
        /usr/lib/ruby/gems/2.0.0/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `execute'
        /usr/lib/ruby/gems/2.0.0/gems/activerecord-4.0.2/lib/active_record/connection_adapters/mysql2_adapter.rb:222:in `execute'
        /usr/lib/ruby/gems/2.0.0/gems/activerecord-4.0.2/lib/active_record/connection_adapters/mysql2_adapter.rb:226:in `exec_query'
        /usr/lib/ruby/gems/2.0.0/gems/activerecord-4.0.2/lib/active_record/connection_adapters/mysql2_adapter.rb:235:in `select'
        /usr/lib/ruby/gems/2.0.0/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract/database_statements.rb:24:in `selec
t_all'
        /usr/lib/ruby/gems/2.0.0/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract/query_cache.rb:63:in `select_all'

Running the same with unicorn (single-threaded webserver) everything's fine.

@sodabrew
Copy link
Collaborator

What version of mysql2, what version of libmysqlclient?

@bwalex
Copy link
Author

bwalex commented Dec 16, 2013

mysql2 (0.3.14)

libmariadbclient 5.5.34-3

same problem with:

ii libmysqlclient18 5.5.32-0ubuntu0.12.04.1 MySQL database client library

@sodabrew
Copy link
Collaborator

Huh. That should just work. Could you show me the output of mysql_config --libs and mysql_config --libs_r ?

@bwalex
Copy link
Author

bwalex commented Dec 17, 2013

On the mariadb machine:

% mysql_config --libs
-L/usr/lib -lmysqlclient -lpthread -lz -lm -lssl -lcrypto -ldl


% mysql_config --libs_r 
-L/usr/lib -lmysqlclient_r -lpthread -lz -lm -lssl -lcrypto -ldl

On the other one:

% mysql_config --libs
-L/usr/lib/x86_64-linux-gnu -lmysqlclient -lpthread -lz -lm -lrt -ldl

% mysql_config --libs_r 
-L/usr/lib/x86_64-linux-gnu -lmysqlclient_r -lpthread -lz -lm -lrt -ldl

@sodabrew
Copy link
Collaborator

According to this line in extconf.rb, MySQL 5.5+ is already thread-safe without the _r variant: https://github.com/brianmario/mysql2/blob/master/ext/mysql2/extconf.rb#L59 I wonder if this isn't true or if there is some other nuance about it.

@bwalex
Copy link
Author

bwalex commented Dec 18, 2013

In 5.5 the _r versions are just symlinked to the normal ones.

@sodabrew
Copy link
Collaborator

That's what I thought, so we're not missing anything obvious there :)

mysql2 is designed and intended to be thread-safe, so if your test case can help turn up bugs in that, I'm happy to take patches and work on it!

@bwalex
Copy link
Author

bwalex commented Dec 28, 2013

Well, I've come up with a smaller test case, without puma, etc, which makes debugging significantly easier.

The code is at https://github.com/bwalex/mysql2_461

To try it, you'll have to adjust the path of the mysql2 gem in the Gemfile as it's currently set to use my local copy.

Run with

bundle exec ruby ./test.rb

It fails quite miserably with the code that is checked in. However, commenting out the following line in test.rb

      #ActiveRecord::Base.connection_pool.connections.map(&:verify!)

seems to make it work. That's also consistent with the fact that most backtraces end up including nogvl_ping. Someone familiar with the code should be able to track down what's going on. My guess is that nogvl_ping needs to be locking or holding a structure that is getting ripped out from under it when running a query just after the verify/ping.

As expected, it also fails using &:active? instead of &:verify!

@bwalex
Copy link
Author

bwalex commented Dec 28, 2013

Some more details below. In this case, mysql ends up with a client structure with a NULL vio, which later blows up. Not too familiar with all the internals at work here, but it looks like the same client structure is being reused between threads, so it's blowing up because some other thread clears the vio.

I see how that might happen if ActiveRecord::Base.connection_pool.connections.map() operates on all connections, including connections used by other threads. If that's the case, at the very least the 'ping' operation (and possibly also connect, disconnect, etc) would have to interlock against any other operation with that same mysql client structure. It's probably fair enough not to, but a warning about this scenario would be appropriate.

0x00007ffff3b1a5d1 in my_real_read (net=0x7fff74000f70, complen=complen@entry=0x7fffab4f2930)
    at /tmp/mariadb/src/mariadb-5.5.34/sql/net_serv.cc:888
888               if (vio_errno(net->vio) == SOCKET_EINTR)
(gdb) bt
#0  0x00007ffff3b1a5d1 in my_real_read (net=0x7fff74000f70, complen=complen@entry=0x7fffab4f2930)
    at /tmp/mariadb/src/mariadb-5.5.34/sql/net_serv.cc:888
#1  0x00007ffff3b1b3bc in my_net_read (net=net@entry=0x7fff74000f70)
    at /tmp/mariadb/src/mariadb-5.5.34/sql/net_serv.cc:1026
#2  0x00007ffff3b0e4ed in cli_safe_read (mysql=mysql@entry=0x7fff74000f70)
    at /tmp/mariadb/src/mariadb-5.5.34/sql-common/client.c:740
#3  0x00007ffff3b12f03 in cli_advanced_command (mysql=0x7fff74000f70, command=<optimized out>, 
    header=0x0, header_length=0, arg=0x0, arg_length=0, skip_check=0 '\000', stmt=0x0)
    at /tmp/mariadb/src/mariadb-5.5.34/sql-common/client.c:882
#4  0x00007ffff3b09a84 in mysql_ping (mysql=<optimized out>)
    at /tmp/mariadb/src/mariadb-5.5.34/libmysql/libmysql.c:979
#5  0x00007ffff3fddcf6 in nogvl_ping (ptr=0x7fff74000f70) at client.c:937
#6  0x00007ffff7b02815 in ?? () from /usr/lib/libruby.so.2.0
#7  0x00007ffff3fddd66 in rb_mysql_client_ping (self=12456560) at client.c:954
#8  0x00007ffff7ae38f4 in ?? () from /usr/lib/libruby.so.2.0
#9  0x00007ffff7ae6dcc in ?? () from /usr/lib/libruby.so.2.0
#10 0x00007ffff7aebaf7 in ?? () from /usr/lib/libruby.so.2.0
#11 0x00007ffff7aec624 in ?? () from /usr/lib/libruby.so.2.0
#12 0x00007ffff7aed9ae in ?? () from /usr/lib/libruby.so.2.0
#13 0x00007ffff7af42e4 in rb_yield () from /usr/lib/libruby.so.2.0
#14 0x00007ffff79b620d in ?? () from /usr/lib/libruby.so.2.0
#15 0x00007ffff7ae38f4 in ?? () from /usr/lib/libruby.so.2.0
#16 0x00007ffff7ae6d55 in ?? () from /usr/lib/libruby.so.2.0
#17 0x00007ffff7aebaf7 in ?? () from /usr/lib/libruby.so.2.0
#18 0x00007ffff7af2611 in ?? () from /usr/lib/libruby.so.2.0
#19 0x00007ffff79ebf66 in rb_rescue2 () from /usr/lib/libruby.so.2.0
#20 0x00007ffff7ae2bae in ?? () from /usr/lib/libruby.so.2.0
#21 0x00007ffff7ae38f4 in ?? () from /usr/lib/libruby.so.2.0
#22 0x00007ffff7ae6d55 in ?? () from /usr/lib/libruby.so.2.0
#23 0x00007ffff7aebaf7 in ?? () from /usr/lib/libruby.so.2.0
#24 0x00007ffff7aeeb36 in ?? () from /usr/lib/libruby.so.2.0
#25 0x00007ffff7aef556 in ?? () from /usr/lib/libruby.so.2.0
#26 0x00007ffff7aef59a in ?? () from /usr/lib/libruby.so.2.0
#27 0x00007ffff7b0132d in ?? () from /usr/lib/libruby.so.2.0
#28 0x00007ffff7b014f0 in ?? () from /usr/lib/libruby.so.2.0
#29 0x00007ffff73c30a2 in start_thread () from /usr/lib/libpthread.so.0
#30 0x00007ffff76bd3dd in clone () from /usr/lib/libc.so.6
(gdb) p net
$1 = (NET *) 0x7fff74000f70
(gdb) p *net
$2 = {vio = 0x0, buff = 0x0, buff_end = 0x7fff740081c0 "0b", write_pos = 0x7fff740061c0 "\001", 
  read_pos = 0x7fff740061c0 "\001", fd = 9, remain_in_buf = 0, length = 0, buf_length = 0, where_b = 0, 
  max_packet = 8192, max_packet_size = 1073741824, pkt_nr = 1, compress_pkt_nr = 0, 
  write_timeout = 31536000, read_timeout = 31536000, retry_count = 1, fcntl = 0, return_status = 0x0, 
  reading_or_writing = 1 '\001', save_char = 0 '\000', net_skip_rest_factor = 0 '\000', 
  unused1 = 0 '\000', compress = 0 '\000', unused3 = 0 '\000', unused = 0x0, last_errno = 2013, 
  error = 0 '\000', unused4 = 0 '\000', unused5 = 0 '\000', 
  last_error = "Lost connection to MySQL server during query", '\000' <repeats 467 times>, 
  sqlstate = "HY000", extension = 0x0}
(gdb) p net->vio
$3 = (Vio *) 0x0
(gdb) frame 5
#5  0x00007ffff3fddcf6 in nogvl_ping (ptr=0x7fff74000f70) at client.c:937
937       return (void *)(mysql_ping(client) == 0 ? Qtrue : Qfalse);
(gdb) p client
$4 = (MYSQL *) 0x7fff74000f70
(gdb) p *client
$5 = {net = {vio = 0x0, buff = 0x0, buff_end = 0x7fff740081c0 "0b", write_pos = 0x7fff740061c0 "\001", 
    read_pos = 0x7fff740061c0 "\001", fd = 9, remain_in_buf = 0, length = 0, buf_length = 0, 
    where_b = 0, max_packet = 8192, max_packet_size = 1073741824, pkt_nr = 1, compress_pkt_nr = 0, 
    write_timeout = 31536000, read_timeout = 31536000, retry_count = 1, fcntl = 0, return_status = 0x0, 
    reading_or_writing = 1 '\001', save_char = 0 '\000', net_skip_rest_factor = 0 '\000', 
    unused1 = 0 '\000', compress = 0 '\000', unused3 = 0 '\000', unused = 0x0, last_errno = 2013, 
    error = 0 '\000', unused4 = 0 '\000', unused5 = 0 '\000', 
    last_error = "Lost connection to MySQL server during query", '\000' <repeats 467 times>, 
    sqlstate = "HY000", extension = 0x0}, connector_fd = 0x0, host = 0x7fff740019a0 "localhost", 
  user = 0x7fff740019f0 "root", passwd = 0x7fff74001a10 "", 
  unix_socket = 0x7fff740019b0 "/run/mysqld/mysqld.sock", 
  server_version = 0x7fff740019c8 "5.5.34-MariaDB-log", 
  host_info = 0x7fff74001980 "Localhost via UNIX socket", info = 0x0, db = 0x7fff74001a30 "test", 
  charset = 0x7ffff3fc21a0 <my_charset_utf8_general_ci>, fields = 0x0, field_alloc = {free = 0x0, 
    used = 0x0, pre_alloc = 0x0, min_malloc = 32, block_size = 8152, block_num = 4, 
    first_block_usage = 0, error_handler = 0x0}, affected_rows = 18446744073709551615, insert_id = 0, 
  extra_info = 0, thread_id = 891, packet_length = 1, port = 0, client_flag = 2148442767, 
  server_capabilities = 18446744072099985407, protocol_version = 10, field_count = 0, 
  server_status = 2, server_language = 33, warning_count = 0, options = {connect_timeout = 0, 
    read_timeout = 0, write_timeout = 0, port = 0, protocol = 2, client_flag = 128, host = 0x0, 
    user = 0x0, password = 0x0, unix_socket = 0x0, db = 0x0, init_commands = 0x0, my_cnf_file = 0x0, 
    my_cnf_group = 0x0, charset_dir = 0x0, charset_name = 0x7fff74001f50 "utf8", ssl_key = 0x0, 
    ssl_cert = 0x0, ssl_ca = 0x0, ssl_capath = 0x0, ssl_cipher = 0x0, shared_memory_base_name = 0x0, 
    max_allowed_packet = 0, use_ssl = 0 '\000', compress = 0 '\000', named_pipe = 0 '\000', 
    unused1 = 0 '\000', unused2 = 0 '\000', unused3 = 0 '\000', unused4 = 0 '\000', 
    methods_to_use = MYSQL_OPT_GUESS_CONNECTION, client_ip = 0x0, secure_auth = 0 '\000', 
    report_data_truncation = 1 '\001', local_infile_init = 0x7ffff3fdbd82 <mysql2_local_infile_init>, 
    local_infile_read = 0x7ffff3fdbea2 <mysql2_local_infile_read>, 
    local_infile_end = 0x7ffff3fdbf22 <mysql2_local_infile_end>, 
    local_infile_error = 0x7ffff3fdbf7f <mysql2_local_infile_error>, 
    local_infile_userdata = 0x7fff74000d70, extension = 0x0}, status = MYSQL_STATUS_READY, 
  free_me = 0 '\000', reconnect = 0 '\000', scramble = "d8)a2snNy9O`sC4w}1x.", unused1 = 0 '\000', 
  unused2 = 0x0, unused3 = 0x0, unused4 = 0x0, unused5 = 0x0, stmts = 0x0, 
  methods = 0x7ffff3fbdb00 <client_methods>, thd = 0x0, unbuffered_fetch_owner = 0x0, 
  info_buffer = 0x0, extension = 0x0}

@sodabrew
Copy link
Collaborator

Nice debugging! Each mysql2 client instance has self-contained resources, so in that respect there's no thread-safety problem. But we're not protecting the user from grabbing handles across threads, so far we've left that to be an application or connection pool implementation issue.

@dimroc
Copy link

dimroc commented Mar 10, 2014

I'm also running into a similar issue when running Puma against MySql2. The returned error varies which would imply a threading issue. Here is the lowest level stack we've encountered:

loading seed: db/seeds/sic_codes.rb
*** glibc detected *** /home/runner/.rbenv/versions/2.1.0/bin/ruby: double free or corruption (!prev): 0x00007f6b99e4bf50 ***
======= Backtrace: =========
/lib/x86_64-linux-gnu/libc.so.6(+0x7eb96)[0x7f6b900e1b96]
/usr/lib/x86_64-linux-gnu/libmysqlclient.so.18(vio_delete+0x1f)[0x7f6b8aa5e75f]
/usr/lib/x86_64-linux-gnu/libmysqlclient.so.18(end_server+0x35)[0x7f6b8aa49715]
/usr/lib/x86_64-linux-gnu/libmysqlclient.so.18(cli_safe_read+0xf8)[0x7f6b8aa498c8]
/usr/lib/x86_64-linux-gnu/libmysqlclient.so.18(+0x36928)[0x7f6b8aa4a928]
/home/runner/bulk_update/vendor/bundle/ruby/2.1.0/extensions/x86_64-linux/2.1.0-static/mysql2-0.3.11/mysql2/mysql2.so(+0x4399)[0x7f6b8af5e399]
/home/runner/.rbenv/versions/2.1.0/bin/ruby(+0x16d64e)[0x7f6b9131364e]
/home/runner/bulk_update/vendor/bundle/ruby/2.1.0/extensions/x86_64-linux/2.1.0-static/mysql2-0.3.11/mysql2/mysql2.so(+0x4c97)[0x7f6b8af5ec97]
/home/runner/bulk_update/vendor/bundle/ruby/2.1.0/extensions/x86_64-linux/2.1.0-static/mysql2-0.3.11/mysql2/mysql2.so(+0x4f1e)[0x7f6b8af5ef1e]
/home/runner/.rbenv/versions/2.1.0/bin/ruby(+0x14baea)[0x7f6b912f1aea]
/home/runner/.rbenv/versions/2.1.0/bin/ruby(+0x14fa4e)[0x7f6b912f5a4e]
/home/runner/.rbenv/versions/2.1.0/bin/ruby(+0x154ed7)[0x7f6b912faed7]

This stack was caught by our CI server on Semaphore.

@sodabrew
Copy link
Collaborator

@dimroc You are using mysql2 0.3.11. Please upgrade.

@sodabrew
Copy link
Collaborator

@bwalex I missed out on reading your test case code when you posted it, sorry. I'm just reading it now. My comments:

The mysql2 gem does not handle connection locking; we're leaving that up to the connection pool implementation. The Active Record Connection Pool provides the tools for this, per http://api.rubyonrails.org/classes/ActiveRecord/ConnectionAdapters/ConnectionPool.html

Connections can be obtained and used from a connection pool in several ways:

Simply use ActiveRecord::Core#connection as with Active Record 2.1 and earlier (pre-connection-pooling). Eventually, when you're done with the connection(s) and wish it to be returned to the pool, you call ActiveRecord::Base.clear_active_connections!. This will be the default behavior for Active Record when used in conjunction with Action Pack's request handling cycle.

Manually check out a connection from the pool with ActiveRecord::Base.connection_pool.checkout. You are responsible for returning this connection to the pool when finished by calling ActiveRecord::Base.connection_pool.checkin(connection).

Use ActiveRecord::Base.connection_pool.with_connection(&block), which obtains a connection, yields it as the sole argument to the block, and returns it to the pool after the block completes.

So this code fails, as expected, because you're not using the thread checkout functions:

def run_test
  puts "Thread #{Thread.current.object_id} reporting for duty."
  loop do
    #ActiveRecord::Base.connection_pool.with_connection do
      ActiveRecord::Base.connection_pool.connections.map(&:verify!)
      Test.all.to_a
      ActiveRecord::Base.clear_active_connections!
    #end
  end
end

t = []
(1..32).each do |i|
  t << Thread.new { run_test }
end

t.each { |thread| thread.join }

@dimroc
Copy link

dimroc commented Mar 10, 2014

Pasted that call stack to show the similarity with OP. Continue to see spurious errors on mysql2 0.3.15 with the following callstacks. Seems to succeed 50% of the time. This does not repro when running on a single thread via unicorn as opposed to puma.

undefined method `fields' for nil:NilClass
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/mysql2_adapter.rb:227:in `exec_query'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/mysql2_adapter.rb:235:in `select'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract/database_statements.rb:24:in `select_all'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract/query_cache.rb:63:in `select_all'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract/database_statements.rb:30:in `select_one'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract/database_statements.rb:36:in `select_value'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/relation/finder_methods.rb:174:in `exists?'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/querying.rb:3:in `exists?'
/Users/dimitrib/workspace/bulk_update/db/seeds/sic_codes.rb:22:in `block (2 levels) in <top (required)>'
Mysql2::Error: MySQL server has gone away: SELECT  1 AS one FROM `sic_codes`  WHERE `sic_codes`.`code` = '263102' AND `sic_codes`.`name` = 'Paperboard Mills (Mfrs)' AND `sic_codes`.`aliases` IN ('paperboard recycled') AND `sic_codes`.`description` IS NULL AND `sic_codes`.`status` = 'active' AND `sic_codes`.`parent_id` = 376 AND `sic_codes`.`lft` = 4014 AND `sic_codes`.`rgt` = 4015 LIMIT 1
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `query'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `block in execute'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract_adapter.rb:435:in `block in log'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activesupport-4.0.2/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract_adapter.rb:430:in `log'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `execute'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/mysql2_adapter.rb:222:in `execute'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/mysql2_adapter.rb:226:in `exec_query'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/mysql2_adapter.rb:235:in `select'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract/database_statements.rb:24:in `select_all'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract/query_cache.rb:63:in `select_all'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract/database_statements.rb:30:in `select_one'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract/database_statements.rb:36:in `select_value'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/relation/finder_methods.rb:174:in `exists?'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/querying.rb:3:in `exists?'
/Users/dimitrib/workspace/bulk_update/db/seeds/sic_codes.rb:22:in `block (2 levels) in <top (required)>'

This is assuming that the rails stack (activerecord) is handling the connection pool you previously mentioned.

@sodabrew
Copy link
Collaborator

This is weird. I would expect that Rails itself uses its own connection pooling correctly. Do you know if Puma is using a mix of threads and processes? I wonder if the fix that landed in a2bcfd6 would help here, if Puma uses a connection pool shared across processes (as well as threads).

@dimroc
Copy link

dimroc commented Mar 10, 2014

Run locally, puma's a single process running approximately 16 threads. If you would like, I can try a particular SHA on mysql2 to help isolate the issue. Both 0.3.11 and 0.3.15 showed the issue. Let me know if there's anything particular you would like me to try.

@sodabrew
Copy link
Collaborator

Thank you! Yes, please try revision a2bcfd6 as well.

@dimroc
Copy link

dimroc commented Mar 11, 2014

Hi @sodabrew ,
Unfortunately the same issue repros when using that SHA:

loading seed: db/seeds/sic_codes.rb
rake aborted!
Mysql2::Error: Lost connection to MySQL server during query: SELECT  1 AS one FROM `sic_codes`  WHERE `sic_codes`.`code` = '229898' AND `sic_codes`.`name` = 'Twines & Cordage Manufacturers' AND `sic_codes`.`aliases` IN ('cordage & twine (mfrs)') AND `sic_codes`.`description` IS NULL AND `sic_codes`.`status` = 'active' AND `sic_codes`.`parent_id` = 284 AND `sic_codes`.`lft` = 3134 AND `sic_codes`.`rgt` = 3135 LIMIT 1
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `query'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:287:in `block in execute'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract_adapter.rb:435:in `block in log'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activesupport-4.0.2/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
/Users/dimitrib/.rvm/gems/ruby-2.1.0@bulk_update/gems/activerecord-4.0.2/lib/active_record/connection_adapters/abstract_adapter.rb:430:in `log'

@sodabrew sodabrew added this to the 0.3.17 milestone Jul 29, 2014
@sodabrew
Copy link
Collaborator

#530 may be a full resolution to this issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants