Bug #27655 Excessive SHOW VARIABLES LIKE 'tx_isolation'
Submitted: 4 Apr 2007 18:09 Modified: 13 Apr 2007 8:31
Reporter: Jeremy Cole (Basic Quality Contributor) (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:Connector / J Severity:S3 (Non-critical)
Version:5.0.5 OS:Any
Assigned to: CPU Architecture:Any

[4 Apr 2007 18:09] Jeremy Cole 
Description:
MySQL Connector/J 5.0.5 is issuing a SHOW VARIABLES LIKE 'tx_isolation' from Connection.getTransactionIsolation with the following code:

if (versionMeetsMinimum(4, 0, 3)) {
  query = "SHOW VARIABLES LIKE 'tx_isolation'"; 
} else {
  query = "SHOW VARIABLES LIKE 'transaction_isolation'";
}

This is called from ReplicationConnection.swapConnections every time.

This should use SELECT @@session.tx_isolation instead (or even better, cache the value?), as SHOW VARIABLES LIKE is not very cheap, and seems to only get more expensive with time (INFORMATION_SCHEMA, etc.).  Note the different code path taken by the two:

mysql> show profiles;
+----------+------------+------------------------------------+
| Query_ID | Duration   | Query                              |
+----------+------------+------------------------------------+
|        0 | 0.00008700 | set profiling = 1                  | 
|        1 | 0.00105600 | show variables like 'tx_isolation' | 
|        2 | 0.00014700 | select @@session.tx_isolation      | 
+----------+------------+------------------------------------+

mysql> show profile source for query 1;
+--------------------+------------+-----------------------+---------------+-------------+
| Status             | Duration   | Source_function       | Source_file   | Source_line |
+--------------------+------------+-----------------------+---------------+-------------+
| Opening tables     | 0.00003800 | open_tables           | sql_base.cc   |        2106 | 
| System lock        | 0.00004800 | mysql_lock_tables     | lock.cc       |         153 | 
| Table lock         | 0.00000600 | mysql_lock_tables     | lock.cc       |         162 | 
| init               | 0.00001100 | mysql_select          | sql_select.cc |        2073 | 
| optimizing         | 0.00001300 | optimize              | sql_select.cc |         617 | 
| statistics         | 0.00000600 | optimize              | sql_select.cc |         773 | 
| preparing          | 0.00001300 | optimize              | sql_select.cc |         783 | 
| executing          | 0.00001200 | exec                  | sql_select.cc |        1407 | 
| Sending data       | 0.00007800 | exec                  | sql_select.cc |        1925 | 
| end                | 0.00075100 | mysql_select          | sql_select.cc |        2118 | 
| query end          | 0.00001000 | mysql_execute_command | sql_parse.cc  |        5085 | 
| freeing items      | 0.00000600 | mysql_parse           | sql_parse.cc  |        5973 | 
| closing tables     | 0.00001600 | dispatch_command      | sql_parse.cc  |        2120 | 
| removing tmp table | 0.00000500 | free_tmp_table        | sql_select.cc |        9856 | 
| closing tables     | 0.00003100 | free_tmp_table        | sql_select.cc |        9884 | 
| logging slow query | 0.00000700 | log_slow_statement    | sql_parse.cc  |        2178 | 
| cleaning up        | 0.00000500 | dispatch_command      | sql_parse.cc  |        2143 | 
+--------------------+------------+-----------------------+---------------+-------------+
17 rows in set (0.00 sec)

mysql> show profile source for query 2;
+----------------------+------------+-----------------------+---------------+-------------+
| Status               | Duration   | Source_function       | Source_file   | Source_line |
+----------------------+------------+-----------------------+---------------+-------------+
| checking permissions | 0.00004100 | check_access          | sql_parse.cc  |        5256 | 
| Opening tables       | 0.00000800 | open_tables           | sql_base.cc   |        2106 | 
| init                 | 0.00001200 | mysql_select          | sql_select.cc |        2073 | 
| optimizing           | 0.00001800 | optimize              | sql_select.cc |         617 | 
| executing            | 0.00000600 | exec                  | sql_select.cc |        1407 | 
| end                  | 0.00002600 | mysql_select          | sql_select.cc |        2118 | 
| query end            | 0.00000800 | mysql_execute_command | sql_parse.cc  |        5085 | 
| freeing items        | 0.00000600 | mysql_parse           | sql_parse.cc  |        5973 | 
| logging slow query   | 0.00001600 | log_slow_statement    | sql_parse.cc  |        2178 | 
| cleaning up          | 0.00000600 | dispatch_command      | sql_parse.cc  |        2143 | 
+----------------------+------------+-----------------------+---------------+-------------+
10 rows in set (0.00 sec)

This is causing a system with already fairly high CPU to spend a lot of real time in SHOW VARIABLES.

How to repeat:
ReplicationConnection.swapConnections
[4 Apr 2007 18:41] Mark Matthews 
For now, a workaround would be to add useLocalSessionState=true to your JDBC url, and the driver will "trust" the state for autocommit and transaction isolation that it has cached.

I'll look into SELECT @@session.tx_isolation, but recently it re-surfaced that there are bugs surrounding that functionality always returning the correct transaction isolation level.
[5 Apr 2007 5:38] Bugs System 
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/23855
[13 Apr 2007 8:31] MC Brown 
A note has been added to the 5.0.6 changelog.