stmt.execute cause Error: 2014 (CR_COMMANDS_OUT_OF_SYNC)

[kamipo]

• ruby 2.2.3p173 (2015-08-18 revision 51636) [x86_64-darwin14]
• OS X 10.10.5

require 'mysql2'

client = Mysql2::Client.new(
  host: 'localhost',
  username: 'root',
  database: 'mysql',
)

begin
  num = 0
  3000.times do |n|
  #10000.times do |n|
    num = n
    stmt = client.prepare('SELECT * FROM user LIMIT 1')
    # stmt = client.prepare('SELECT 1')
    stmt.execute
  end
rescue
  p num
  p $! # <Mysql2::Error: Commands out of sync; you can't run this command now>
end

[sodabrew]

There is a limit to the number of prepared statements, perhaps you're hitting it?
https://dev.mysql.com/doc/refman/5.0/en/server-system-variables.html#sysvar_max_prepared_stmt_count

[kamipo]

No. If adding client.query('SET GLOBAL max_prepared_stmt_count = 1'), it causes following error:

#<Mysql2::Error: Can't create more than max_prepared_stmt_count statements (current value: 1)>

[kamipo]

https://dev.mysql.com/doc/refman/5.6/en/commands-out-of-sync.html:

If you get Commands out of sync; you can't run this command now in your client code, you are calling client functions in the wrong order.

This can happen, for example, if you are using mysql_use_result() and try to execute a new query before you have called mysql_free_result(). It can also happen if you try to execute two queries that return data without calling mysql_use_result() or mysql_store_result() in between.

[sodabrew]

Interesting, ok. I'll see what I can figure out. Thank you for testing the 0.4.x releases more heavily, btw!

[justincase]

I don't see any exceptions with a loop of <= ~1650. Race conditions?

[sodabrew]

I can reproduce the error with the given script. If you close the statement handle on each loop, it works fine. I agree it would be best to provide some kind of better warning or cleanup to prevent this, but I'm not sure what that would be...

  10000.times do |n|
    stmt = client.prepare('SELECT * FROM mysql2_test LIMIT 1')
    stmt.execute
    stmt.close # adding this line lets it run all the way through
  end

[justincase]

Replacing stmt.close with GC.start works as well, so something isn't cleanup properly? According to commands-out-of-sync, mysql_free_result() should be sufficient (without closing/deallocating the stmt).

[sodabrew]

Oh that makes sense actually! Ruby GC might be calling for a statement deallocate while the connection is in an incompatible state, such as being in the middle of returning a result set. Some printf or wire shark debugging might help identify just which commands are getting mixed up.

[sodabrew]

Yep, it's totally that Ruby GC is getting in the middle.

With this loop, the order of mysql_stmt_foo calls is:

  10000.times do |n|
    stmt = client.prepare('SELECT * FROM mysql2_test LIMIT 1')
    stmt.execute
    GC.start
    print '.'
  end

mysql_stmt_init
mysql_stmt_prepare
mysql_stmt_execute
mysql_stmt_store_result
mysql_stmt_free_result
mysql_stmt_close
.

Without the GC.start call, the order is more varied, as the mysql_stmt_free_result and mysql_stmt_close calls occur somewhat randomly. At the point of failure, I see this ordering:

mysql_stmt_init
mysql_stmt_prepare
mysql_stmt_execute
mysql_stmt_close
mysql_stmt_store_result

Crucially, mysql_stmt_execute must be followed by mysql_stmt_store_result. Incidentally, this is pretty much what is warned in the MySQL docs: http://dev.mysql.com/doc/refman/5.7/en/mysql-stmt-execute.html (In the doc formysql_stmt_execute, it says that you have to call mysql_stmt_fetch next, but in the doc for mysql_stmt_fetch it says that you can call mysql_stmt_store_result first to buffer the result on the client side, then call mysql_stmt_fetch to get each row.)

So... bottom line, I think that we need to ensure that GC doesn't run between mysql_stmt_execute and mysql_stmt_store_result. Turns out there is a way to do this! http://ruby-doc.org/core-1.8.7/GC.html#method-c-disable

I'll link a test PR shortly.

[sodabrew]

@kamipo I was testing this a bit more, and found that this loop runs well:

  10000.times do |n|
    num = n
    stmt = client.prepare('SELECT * FROM mysql2_test LIMIT 1')
    stmt.execute
    stmt.close
  end

The proximate cause of failure being a GC of the stmt handle happening mid-way through the next loop, and so mysql_stmt_close happens at a bad time.

Would it be possible in your ActiveRecord work to make sure that statement handles are explicitly closed when they are removed from the handle cache?

Edit: apparently I re-discovered my own findings from #694 (comment) gah.

[sodabrew]

After reading through rails/rails#22415 it looks like the statement handles are always being freed. Maybe I should revisit your proposed Result.free from #692 ? That would also simplify the differences between mysql and mysql2 drivers, e.g. in AR the implementation for execute_and_free could move up to abstract_mysql_adapter for both.

[sodabrew]

Resolved by #729 - I'll add to the README that it is highly recommended to free results when using prepared statements.

[kamipo]

This issue is not resolved by #729. #729 can not prevent GC between mysql_stmt_execute and mysql_stmt_store_result (see #705).

require 'mysql2'

client = Mysql2::Client.new(
  host: 'localhost',
  username: 'root',
  database: 'mysql',
)

begin
  num = nil 
  3000.times do |n| 
    num = n 
    stmt = client.prepare('SELECT * FROM user LIMIT 1')
    result = stmt.execute
    result.free # added by https://github.com/brianmario/mysql2/pull/729
  end
rescue
  p num 
  p $! # <Mysql2::Error: Commands out of sync; you can't run this command now>
end

Result:

$ bundle exec ruby issue_694.rb
735
#<Mysql2::Error: Commands out of sync; you can't run this command now>

[sodabrew]

Oh, the statement handle can still get garbage-collected out of order.

For the Rails use case, since you are holding the references to the statement handles until you close them explicitly, is it sufficient simply to add Result#free to get Rails with prepared statements fully reliable?

For the general use case, as you show above, it sounds like the only solution is to hold the GVL? I would really hope to find an alternative if possible, to allow parallel execution of statements (i.e. other Ruby threads can continue locally while the MySQL server is processing a query).