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

Improve MySQL error detection #36932

Merged
merged 1 commit into from Aug 15, 2019

Conversation

@kirs
Copy link
Member

commented Aug 14, 2019

On a query that failed due a statement timeout, an exception from mysql2 will get raised which ActiveRecord matches to ActiveRecord::StatementTimeout, based on 3024 error code from the server (https://github.com/rails/rails/blob/master/activerecord/lib/active_record/connection_adapters/abstract_mysql_adapter.rb#L591).

However, thanks to @clandry94 we found an occurrence of ActiveRecord::StatementInvalid (Mysql2::Error: Sort aborted: Query execution was interrupted, maximum statement execution time exceeded) where StatementInvalid is the basic AR error class, which tells us that the error code was != 3024 so AR didn't match it to StatementTimeout. Also, Sort aborted: in the exception message looks suspicious.

I looked in MySQL 5.7 docs and I found another error code:

Error number: 1028; Symbol: ER_FILSORT_ABORT; SQLSTATE: HY000
Message: Sort aborted

It sounds like if the statement was canceled at the stage of filesort, the eror code is going to be 1028, not 3024. I'd love a DBA opinion on whether I'm right or not.

If I'm right, I'd like to raise StatementTimeout on both 1028 and 3024 server errors.
This PR is missing tests which I'll attempt to add once I verify my hypothesis.

Another option to detect StatementTimeout would be to match the error message against maximum statement execution time exceeded, but that doesn't seem great.

@rails-bot rails-bot bot added the activerecord label Aug 14, 2019

@jeremycole

This comment has been minimized.

Copy link
Contributor

commented Aug 14, 2019

👍 This is reasonable.

IMHO, it could be mapped to either StatementTimeout or QueryCanceled, but I don't think that matters all that much. (In fact it's not entirely clear why those are actually separate exception classes when they more or less represent conceptually the same thing, but I think due to history QueryCanceled may imply that your connection is no longer valid, whereas StatementTimeout does not.)

@kamipo

This comment has been minimized.

Copy link
Member

commented Aug 14, 2019

QueryCanceled is used when a query is KILL QUERY query_ided by another thread.
It seems that ER_FILSORT_ABORT is raised when SELECT /*+ MAX_EXECUTION_TIME(msec) */ ... or @@max_execution_time variable are exceeded at the file sorting phase, so StatementTimeout is the better one to me.

@jeremycole

This comment has been minimized.

Copy link
Contributor

commented Aug 14, 2019

Adding: Realistically, MySQL should not leak that differing error code out, as it doesn't matter to the user whether it was interrupted during sort or not. I have reproduced this difference and filed MySQL Bug #96537.

From the MySQL bug report:

A query that gets terminated before sort produces error 3024 as expected:

> select /*+ max_execution_time(50) */ * from t a, t b order by a.pad asc, b.pad desc limit 1;
ERROR 3024 (HY000): Query execution was interrupted, maximum statement execution time exceeded

If the same query is terminated during filesort, error 1028 is produced instead of error 3024:

> select /*+ max_execution_time(300) */ * from t a, t b order by a.pad asc, b.pad desc limit 1;
ERROR 1028 (HY000): Sort aborted: Query execution was interrupted, maximum statement execution time exceeded

👍 to @kirs on the analysis. LGTM.

@jeremy
Copy link
Member

left a comment

Great troubleshoot and fix @kirs.

The PR description lays out the situation well. Would you update the commit message (Improve mysql error detection) to match (discuss the purpose of the change, how you arrived at the decision, etc)? Please add a similar remark to CHANGELOG.md as well!

@kirs kirs force-pushed the kirs:mysql2-filsort-abort branch from abc33df to 403056c Aug 15, 2019

@kirs

This comment has been minimized.

Copy link
Member Author

commented Aug 15, 2019

Thanks for feedback! Added tests and updated the changelog.

Improve detection of ActiveRecord::StatementTimeout with mysql2 adapter
in the edge case when the query is terminated by MySQL server during filesort.
See https://bugs.mysql.com/bug.php?id=96537 for more details.

@kirs kirs force-pushed the kirs:mysql2-filsort-abort branch from 403056c to c99c572 Aug 15, 2019

@kamipo kamipo merged commit 12e2013 into rails:master Aug 15, 2019

1 of 2 checks passed

buildkite/rails Build #63079 failed (10 minutes, 38 seconds)
Details
codeclimate All good!
Details

@kirs kirs deleted the kirs:mysql2-filsort-abort branch Aug 16, 2019

kamipo added a commit that referenced this pull request Aug 22, 2019
Merge pull request #36932 from kirs/mysql2-filsort-abort
Improve MySQL error detection
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
4 participants
You can’t perform that action at this time.