MySQL Bugs: #10210: running SHOW STATUS increments counters it shouldn't

Bug #10210	running SHOW STATUS increments counters it shouldn't
Submitted:	27 Apr 2005 16:49	Modified:	26 Jun 2006 14:42
Reporter:	Tobias Asplund	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Information schema	Severity:	S2 (Serious)
Version:	5.0.5	OS:	FreeBSD (FreeBSD)
Assigned to:	Michael Widenius	CPU Architecture:	Any

Description:
Maybe not a bug, but makes statistics a bit unreliable, especially if you have GUI tools or programs like mysqltop running that run lots of meta-data queries, since you can't trust results from this.

How to repeat:
mysql> FLUSH STATUS;
Query OK, 0 rows affected (0.00 sec)

mysql> SHOW STATUS LIKE 'hand%';
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Handler_commit             | 0     |
| Handler_delete             | 0     |
| Handler_discover           | 0     |
| Handler_prepare            | 0     |
| Handler_read_first         | 0     |
| Handler_read_key           | 0     |
| Handler_read_next          | 0     |
| Handler_read_prev          | 0     |
| Handler_read_rnd           | 0     |
| Handler_read_rnd_next      | 1     |
| Handler_rollback           | 0     |
| Handler_savepoint          | 0     |
| Handler_savepoint_rollback | 0     |
| Handler_update             | 0     |
| Handler_write              | 14    |
+----------------------------+-------+
15 rows in set (0.01 sec)

mysql> SHOW STATUS LIKE 'hand%';
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Handler_commit             | 0     |
| Handler_delete             | 0     |
| Handler_discover           | 0     |
| Handler_prepare            | 0     |
| Handler_read_first         | 0     |
| Handler_read_key           | 0     |
| Handler_read_next          | 0     |
| Handler_read_prev          | 0     |
| Handler_read_rnd           | 0     |
| Handler_read_rnd_next      | 17    |
| Handler_rollback           | 0     |
| Handler_savepoint          | 0     |
| Handler_savepoint_rollback | 0     |
| Handler_update             | 0     |
| Handler_write              | 29    |
+----------------------------+-------+
15 rows in set (0.01 sec)

mysql> SHOW STATUS LIKE 'cr%';
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Created_tmp_disk_tables | 0     |
| Created_tmp_files       | 0     |
| Created_tmp_tables      | 4     |
+-------------------------+-------+

Seems like a SHOW STATUS command inserts rows into a temporary table, then scans this table to retrieve the rows back.

The same happens with SHOW TABLES and most likely a lot of other SHOW commands.

Suggested fix:
SHOW commands should not increment the status counters, since it can skew the results of profiling.

Verified on Slackware 10.0 and BK 5.0 source.

It's even worse now in 5.0.15, now it logs all the show commands to the slow log when running with --log-queries-not-using-indexes

# User@Host: flupps[flupps] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 3  Rows_examined: 3
show tables;
# Time: 051027 12:09:54
# User@Host: flupps[flupps] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 2  Rows_examined: 2
SHOW VARIABLES LIKE 'max_bin%';
# Time: 051027 12:10:05
# User@Host: flupps[flupps] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
SHOW VARIABLES LIKE 'exp%';

Seems like each SHOW command actually is treated like a table scan on a temporary table.

eeyore> SHOW STATUS LIKE 'Select_scan';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Select_scan   | 14    |
+---------------+-------+
1 row in set (0.01 sec)

eeyore> SHOW STATUS LIKE 'Select_scan';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Select_scan   | 15    |
+---------------+-------+
1 row in set (0.01 sec)

Sorry, wrong paste:

eeyore> SHOW STATUS WHERE Variable_name IN('Select_scan', 'created_tmp_tables');
+--------------------+-------+
| Variable_name      | Value |
+--------------------+-------+
| Created_tmp_tables | 131   |
| Select_scan        | 16    |
+--------------------+-------+
2 rows in set (0.00 sec)

eeyore> SHOW STATUS WHERE Variable_name IN('Select_scan', 'created_tmp_tables');
+--------------------+-------+
| Variable_name      | Value |
+--------------------+-------+
| Created_tmp_tables | 132   |
| Select_scan        | 17    |
+--------------------+-------+
2 rows in set (0.01 sec)

The same "bug" exists with INFORMATION_SCHEMA. These commands also skew statistics. It is even worse with IS though as they don't get logged anywhere. At least for SHOW there are the Com_show_* status variables. For IS there is nothing. Furthermore one query can cause *a lot* of temp table creations: 

mysql> show status like 'Created%';
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Created_tmp_disk_tables | 0     |
| Created_tmp_files       | 0     |
| Created_tmp_tables      | 1     |
+-------------------------+-------+
3 rows in set (0.01 sec)

12:07 information_schema> select * from information_schema.tables;
<cut>

232 rows in set, 2 warnings (1.65 sec)

12:07 information_schema> show status like 'Created%';
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Created_tmp_disk_tables | 5     |
| Created_tmp_files       | 0     |
| Created_tmp_tables      | 42    |
+-------------------------+-------+
3 rows in set (0.00 sec)

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/6297

The problem with slow log is filed in the bug #19764: SHOW commands end up in the slow log as table scans).

I meant, add the difference to the global statistics.

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/7381

The suggested patch fixes the critical problem, but extend a very common execution path with a couple of if's, which is not good.

The problem is that we have 'kind of a mess' with how SQLCOM_STATUS is implemented by usage of sql_command and orig_sql_command as we don't have any unique code that is executed in sql_parse.cc as part of SQLCOM_STATUS.

I propose instead that we remove orig_sql_command, move the code in mysql_execute_command(), SQLCOM_SELECT to a function and add case statements in mysql_execute_command() to handle the SQLCOM_STATUS... commands.

This will make the current patch easier to implement (no changes in sql_select.cc) and will also allow us to remove some code from sql_select.cc to the proper place.

I will try to implement the above and let Ramil review it.

Regarding the issue that SHOW increments the global counters:
I think this is important that the global counters are updated as otherwise one will not see the inpact that the SHOW commands can have on the system. (As issuing many SHOW commands frequetly on the server can have a serious impact if we have to create disk based temporary tables).

I agree however that SHOW commands shouldn't show up in the slow query log and we will fix this as part of this patch. (See bug#19764)

We have a flag for --log-queries-not-using-indexes and similar help for profiling.
The status information will be very hard (if not impossible) to use for profiling since show status will show up as table scans (SHOW STATUS LIKE 'Select_scan') which will make the noise ratio very high as soon as you have some kind of monitoring application (MySQL Network, Cacti, etc).
Would it be possible to implement a flag in 5.1 that optionally disables incrementing counters for SHOW commands/queries against Information_schema?

Or could we at least make SHOW LOCAL STATUS not count them?
Since it is possible to have your monitoring application count how many commands it runs and subtract its own statistics manually (although, a big hassle).

Also,
Since EXPLAIN sometimes will not show the execution plan, sometimes you will have to go down to handler_* and look, but those also gets tainted by running SHOW to display their values - so even to see a single query's execution via handler_ calls will not be correct.

About last comment:

- SHOW STATUS and slow query log is handled in Bug#19764.

The proposed patch will work as follows:
- SHOW STATUS is not logged to slow query log
- SHOW STATUS does not update local status variables (except com_show_status).
- SHOW STATUS will update global status variables to allow one to monitor what the server is really doing (as SHOW STATUS creates some temporary tables that may affect performance if SHOW STATUS is called to often)

Becasue of the extensive cleanups the patch required, this can not be pushed into 5.0, so it will be pushed into the 5.1 tree instead.

Thank you for your bug report. This issue has been committed to our source repository of that product and will be incorporated into the next release.

If necessary, you can access the source repository and build the latest available version, including the bug fix. More information about accessing the source trees is available at

    http://www.mysql.com/doc/en/Installing_source_tree.html

Fix will be in 5.1.11

Sorry, wrong info in last bug entry
Fix will be available in 5.1.12

Documented in 5.1.12 changelog. Closed.