"EXPLAIN SAVEPOINT active_record_1" error in tests with transactions #6458

Closed
holli opened this Issue May 23, 2012 · 10 comments

Comments

Projects
None yet
7 participants
Contributor

holli commented May 23, 2012

Sometimes we are using slower/old machines in development and we started getting following errors in our functional tests:

test: players_table should sort by lastname. (Team::PlayersControllerTest):
ActiveRecord::StatementInvalid: Mysql2::Error: Table 'app_test.savepoint' doesn't exist: EXPLAIN SAVEPOINT active_record_1
    app/controllers/team/players_controller.rb:360:in `get_sort_players'

After a long debugging we increased auto_explain_treshold_in_seconds method in our config/evironment/test.rb

config.active_record.auto_explain_threshold_in_seconds = 30 # originally 0.5

Now all tests pass as they should. We are using mysql (various versions) so I tried the following commands in mysql:

mysql> explain savepoint test_1;
ERROR 1146 (42S02): Table 'app_development.savepoint' doesn't exist
mysql> explain select * from players;
...explanation of the query as expected...

I'm not sure where/what is the problem. Feeling is that it's somehow that rails tries to sql explain slow transaction start? Is that possible? That would results mysql thinking that we are trying to run explain on some table.

Yes, apparently it's trying to run EXPLAIN on a SAVEPOINT query, exploding. I think it should not be running explain on this particular command, as you said, with slower machines taking more than the threshold it'd explode.

As a side note, you can also disable the auto explain feature by setting it to false.
Thanks.

I encountered a similar issue and while I don't think it warrants a new bug ticket, I'll mention it here. Our rails app started prepending "explain" to the query "SHOW max_identifier_length", which isn't valid in postgres. It seems like the feature needs a list of queries it shouldn't prepend onto.

Contributor

holli commented May 25, 2012

List of queries is good. In addition it probably shouldn't result in error if this part fails, only log the error. Now it probably could end as 500 error to users if it would happen in production env? Which is a bit bad thing as the application works otherwise.

For maximum google searchability, here's the error from the log:

: EXPLAIN SHOW max_identifier_length
[INFO 2012-05-25 17:31:40 Web 47683] Completed 500 Internal Server Error in 1112ms
[FATAL 2012-05-25 17:31:40 Web 47683] 
ActiveRecord::StatementInvalid (PGError: ERROR:  syntax error at or near "SHOW"
LINE 1: EXPLAIN SHOW max_identifier_length

Yes, this error resulted in the whole page returning a 500. Fortunately this was development (and the feature is disabled on production). But if anyone enables this feature on production then they're at risk of spitting out 500s.

Contributor

kennyj commented May 26, 2012

I sent related PR #6386 .

Contributor

kennyj commented May 30, 2012

Hey guys !
How about kennyj/rails@4a25742 ?

Owner

rafaelfranca commented May 30, 2012

@kennyj seems good. cc/ @fxn

@ghost ghost assigned fxn May 30, 2012

Owner

fxn commented May 30, 2012

ACK, we already skip some stuff and I'll have a look at the proposed solution.

Contributor

dlee commented Sep 6, 2012

@kennyj is kennyj/rails@4a25742 part of a pull request somewhere?

Contributor

kennyj commented Sep 6, 2012

I didn't sent any PR include 4a25742.

rafaelfranca added a commit that referenced this issue Sep 17, 2012

Backport explain fixes.
* Mark as SCHEMA some schema database queries. #7648
* Don't explain queries except normal CRUD sql. #7657

Closes #6458
Closes #7544
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment