Prepared statements issue (continued)

[jeroenbourgois]

TDLR: the prepare: :unnamed setting seems to have no effect.

We have read through related tickets like #92 and #83 but still want to create a new one.

Our use case is as follows: users can upload xlsx files that contain a large number of rows (+3000) to process. Processing in our case means doing some data cleansing and then insert and or update multiple records across tables.

To execute the queries we use the regular Ecto API, being all/2, one/2, update/2, etc. For each row to be processed, we execute 10 to 15 queries, depending on the flow.

Whilst developing we always used stub files with a very limited amount of rows. Now the client is using actual files with said number of rows, meaning that the number of executed queries quickly ramps up.

Upon the first report of a crash and after seeing the uploaded file, we quickly reasoned that it probably was a timeout on the GET request or something like that. Instead, we saw the error described in the other related issue reports:

MyXQL.Connection (#PID<0.2375.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.2952.0> exited

After that, we ran the process again whilst looking at the :observer and grabbed the messages from the exited PID, where we could read:

#{'__struct__' => 'Elixir.MyXQL.Connection',
  client =>
      #{'__struct__' => 'Elixir.MyXQL.Client',connection_id => 2275,
        sock => {gen_tcp,#Port<0.129>}},
  cursors => #{},
  disconnect_on_error_codes => ['ER_MAX_PREPARED_STMT_COUNT_REACHED'],
  last_ref => nil,ping_timeout => 15000,prepare => unnamed,
  queries => #Ref<0.3597155187.3075080195.95704>,transaction_status => idle}

A bit surprising, since we did not realize we were using prepared statements, but it made perfect sense, considering the amount of queries. We ran it again and while running kept an eye on the server stats for the prepared statement count and although it increased, it was never near the maximum allowed on the server...

Still, it kind of made sense as a possible root cause. We then first tried chunking all rows into smaller lists and processing those with a Process.sleep/1 after each row, to allow the connections to be cleaned up, but the error persisted.

We also tried applying the prepare: :unnamed in our config, but that seemed to do 'nothing' (as in: the count of prepared statements went up none the less). Here is how we provided the option inside config.exs

config :the_app, TheApp.Repo,
  username: System.get_env("DB_USER"),
  password: System.get_env("DB_PASSWORD"),
  database: System.get_env("DB_NAME"),
  hostname: System.get_env("DB_HOST"),
  pool_size: 5,
  pool_overflow: 20,
  timeout: 120_000,
  prepare: :unnamed

As you can see we also tried playing with the pool_size and the pool_overflow variable, the latter which is an unknown option we assume now, it probably should be max_overflow?

With a very low pool size it seems to work, but we still don't understand why the prepared statement count goes up. Also we would prefer to have a pool_size of 10, since that is what we use on all our projects. But then again, none of the other projects with myxql perform that many queries. We have only one other user case that does that, and it worked fine, but it using mariaex. And reverting our current app to mariaex does not seem feasible now, too many deps on myxql and/or Ecto 3.

[josevalim]

Can you please include the MyXQL version in your report?

prepare: :unnamedstill prepares the queries but the queries are closed right after, so you shouldn't see anything more than the number of pool_size * nodes. pool_overflow or max_overflow has no meaning for a couple years (it was an Ecto 1 config iirc).

[jeroenbourgois]

@josevalim I updated the OP and included the version, which is 0.3.1.
We only have one node atm.

[josevalim]

To clarify, you were not supposed to see a leakage, the number of statements should be fixed. If they are growing, then that's definitely a bug (and it may be the bug that forced us to revert #92). So if you have any way to reproduce the leakage, we would absolutely love to take a look at it. :)

[jeroenbourgois]

Update: after all, it just seemed to be the idle_timeout for the cowboy request that was reached. The error we got for it was not expected, so we never looked into that possibility, sadly. A lot of time wasted because of something so obvious... But hey, with hindsight :) The error we got just put us on the wrong foot....

This can be closed I assume, sorry for the false alarm!

So we were able to reproduce it in a standalone project

On my local machine I really had to set a high loop limit, since it won't choke with anything less than a 1000 queries looped :P but still: reproducible. Mileage on loop iterations may vary.

What we noticed is that without the prepare: :unnamed option, the count for closed statements remains 0, when we add the option to the config, it does seem to go up.

Observer some MySQL stats, after a fresh MySQL server restart:

mysql> show variables like 'max_prepared_stmt_count';
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| max_prepared_stmt_count | 16382 |
+-------------------------+-------+
1 row in set (0.00 sec)

mysql> show global status like '%om_stmt%';
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Com_stmt_execute        | 0     |
| Com_stmt_close          | 0     |
| Com_stmt_fetch          | 0     |
| Com_stmt_prepare        | 0     |
| Com_stmt_reset          | 0     |
| Com_stmt_send_long_data | 0     |
| Com_stmt_reprepare      | 0     |
+-------------------------+-------+

Then, running the avalanche of queries using prepare: :unnamed:

mysql> show global status like '%om_stmt%';
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Com_stmt_execute        | 8002  |
| Com_stmt_close          | 8001  |
| Com_stmt_fetch          | 0     |
| Com_stmt_prepare        | 8002  |
| Com_stmt_reset          | 0     |
| Com_stmt_send_long_data | 0     |
| Com_stmt_reprepare      | 0     |
+-------------------------+-------+
7 rows in set (0.00 sec)

[ after about 30 seconds, query again]

mysql> show global status like '%om_stmt%';
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Com_stmt_execute        | 28827 |
| Com_stmt_close          | 28826 |
| Com_stmt_fetch          | 0     |
| Com_stmt_prepare        | 28827 |
| Com_stmt_reset          | 0     |
| Com_stmt_send_long_data | 0     |
| Com_stmt_reprepare      | 0     |
+-------------------------+-------+
7 rows in set (0.00 sec)

So that seems to work, as you stated, the :unnamed option does not prevent prepared statements from being created, but closes them. When we restart the MySQL server and run the exact same app again but without the :unnamed option, the com_stmt_close remains 0.

But then (with or without :unnamed) we still get the error:

MyXQL.Connection (...) disconnected: ** (DBConnection.ConnectionError) client #PID<> exited

And when looking into the :observer see the ER_MAX_PREPARED_STMT_COUNT_REACHED error. And this feels strange, since the number found in com_stmt_execute is far over the max number the server allows? So I am wondering if that is in fact the actual error. I would assume that 'max prepared reached' wount occur right after the count of the max is reached or surpassed, not a couple of 1000 after... Max here was 16382, the statements prepare is 28827. Unless we have to read is as: 28.827 prepared, 28.826 closed, 1 remaining?

Also, most of the time we get that one error and that's it, the rest of the querying stops. But sometimes it just continues and then halts a bit farther down the road.

Sorry we cannot be conclusive, still poking holes here, we hope the dummy project can help to get the root cause. In our first use case, we thought that chunking the rows and handling them with some resting time in between (Process.sleep) would solve the issue, but it does not.

note: after continuous testing, we have the feeling it is not happening when the method is called directly from iex, but only when it is started inside a controller, so with a web request. Seems trivial, but it might be a clue... We tried running from iex several times, it never exits, but when submitting an empty form and then calling the same method, the exit occurs. If the actual request were taking too much time, surely we would see another error from conn, or am I wrong?

[josevalim]

Closing as per the update! Thanks!