Bug #10210 running SHOW STATUS increments counters it shouldn't
Submitted: 27 Apr 2005 18:49 Modified: 26 Jun 2006 16:42
Reporter: Tobias Asplund
Status: Closed
Category:Server: I_S Severity:S2 (Serious)
Version:5.0.5 OS:FreeBSD (FreeBSD)
Assigned to: Bugs System Target Version:

[27 Apr 2005 18:49] Tobias Asplund
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.
[27 Apr 2005 19:06] Miguel Solorzano
Verified on Slackware 10.0 and BK 5.0 source.
[27 Oct 2005 12:21] Tobias Asplund
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%';
[8 Dec 2005 12:37] Tobias Asplund
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)
[8 Dec 2005 12:38] Tobias Asplund
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)
[10 May 2006 12:09] Max Mether
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)
[12 May 2006 12:43] 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/6297
[12 May 2006 13:18] Ramil Kalimullin
The problem with slow log is filed in the bug #19764: SHOW commands end up in the slow log
as table scans).
[15 May 2006 12:24] Ramil Kalimullin
I meant, add the difference to the global statistics.
[8 Jun 2006 11:43] 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/7381
[19 Jun 2006 12:01] Michael Widenius
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)
[19 Jun 2006 17:00] Tobias Asplund
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.
[20 Jun 2006 12:25] Michael Widenius
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.
[26 Jun 2006 15:13] Michael Widenius
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
[26 Jun 2006 15:14] Michael Widenius
Sorry, wrong info in last bug entry
Fix will be available in 5.1.12
[26 Jun 2006 16:42] Jon Stephens
Documented in 5.1.12 changelog. Closed.